Avoid async log4j2 log events to be counted multiple times #2183
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
Hi Guys, When we have an async logger configured a call to log.info or any other level triggers 2 times the filter, i found a way to use the isEndOfBatch attribute from LogEvent to check if this is the last call and then metrics counter will be incremented only once instead of multiple times. I also create a simple spring-boot project to test it locally. You can see it here: /~https://github.com/dennysfredericci/springboot-micrometer-issue-2183 |
Yes, could you please retarget this at the |
shakuzen
force-pushed
the
bugfix/2176-log4j2-async-counter
branch
from
4037853 to
406c19e
Compare
shakuzen
approved these changes
Jul 23, 2020
|
|
||
| assertThat(registry.get("log4j2.events").tags("level", "info").counter().count()).isEqualTo(0); | ||
| logger.info("Hello, world!"); | ||
| assertThat(registry.get("log4j2.events").tags("level", "info").counter().count()).isEqualTo(1); |
There was a problem hiding this comment.
I think we have a race here since the logger is asynchronous, there's no guarantee that the counter will be incremented by this point.
There was a problem hiding this comment.
I still wonder about the theoretical race, but after much debugging, it seems like the issue was probably due to test execution order and global state from before the execution of the newly added test. Changing the cleanup method to @BeforeEach seems to have fixed it consistently for me locally.
The LoggerContext is cached in global state and should be cleared so each test runs in isolation.
shakuzen
changed the title
jonatan-ivanov
added a commit
that referenced
this pull request
Oct 20, 2023
In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253
jonatan-ivanov
added a commit
that referenced
this pull request
Oct 20, 2023
In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253
jonatan-ivanov
added a commit
that referenced
this pull request
Oct 20, 2023
In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253
jonatan-ivanov
added a commit
that referenced
this pull request
Oct 25, 2023
In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253
jonatan-ivanov
added a commit
that referenced
this pull request
Oct 25, 2023
In case of async loggers, the MetricsFilter#filter method is/was called multiple times. Because of this, a check was introduced in gh-2183 assuming that if the event has the isEndOfBatch flag set to true, that is the last filter method call for that event. Unfortunately, it turned out that this approach did not work, since it did not just filter out the unwanted multiple calls on one event but it also filtered out all the filter method calls on events that were not at the end of the async batch. So Log4j2Metrics counted batches of events, not the individual events. Fortunately multiple filter invocations was fixed in Log4j2, see apache/logging-log4j2#1550 and apache/logging-log4j2#1552. Since now there will be only one filter method call, the check introduced in gh-2183 can and should be removed (the call to the filter method is before the isEndOfBatch flag is set so the flag will always return false). Closes gh-2176 See gh-2183 See gh-4253
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Hi all, hello from Belgium! :)
I just create a test for this issue and indeed the filter have been called multiple times for same event.
Fixes #2176