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

Multiple filter invocations in AsyncLoggerConfig #1550

Closed
ppkarwasz opened this issue Jul 12, 2023 · 0 comments · Fixed by #1552
Closed

Multiple filter invocations in AsyncLoggerConfig #1550

ppkarwasz opened this issue Jul 12, 2023 · 0 comments · Fixed by #1552
Assignees
Labels
bug Incorrect, unexpected, or unintended behavior of existing code
Milestone

Comments

@ppkarwasz
Copy link
Contributor

Description

The AsyncLoggerConfig calls AbstractFilterable#isFiltered(LogEvent) three times:

  • twice on the calling thread (for asynchronous and synchronous dispatch),
  • once on the logging thread.

While this is not a problem per se, this causes unnecessary problems to stateful filters like in micrometer-metrics/micrometer#2176.

Configuration

Version: 2.20.0

@ppkarwasz ppkarwasz added the bug Incorrect, unexpected, or unintended behavior of existing code label Jul 12, 2023
@ppkarwasz ppkarwasz added this to the 2.20.1 milestone Jul 12, 2023
@ppkarwasz ppkarwasz self-assigned this Jul 12, 2023
ppkarwasz added a commit to ppkarwasz/logging-log4j2 that referenced this issue Jul 12, 2023
Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.
ppkarwasz added a commit to ppkarwasz/logging-log4j2 that referenced this issue Jul 12, 2023
Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.
ppkarwasz added a commit to ppkarwasz/logging-log4j2 that referenced this issue Jul 12, 2023
Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.
ppkarwasz added a commit to ppkarwasz/logging-log4j2 that referenced this issue Sep 15, 2023
Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.
ppkarwasz added a commit that referenced this issue Sep 16, 2023
Async logger configs call `isFiltered(LogEvent)` multiple times. While
this is not a problem per-se, it can cause a performance penalty if the
filter is slow and creates problems to stateful filters.
jonatan-ivanov added a commit to micrometer-metrics/micrometer that referenced this issue 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 to micrometer-metrics/micrometer that referenced this issue 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 to micrometer-metrics/micrometer that referenced this issue 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 to micrometer-metrics/micrometer that referenced this issue 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 to micrometer-metrics/micrometer that referenced this issue 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
Labels
bug Incorrect, unexpected, or unintended behavior of existing code
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant