Skip to content

fix bug: throttledRateLimiter is not once per minute, but five times#7156

Merged
jack-berg merged 1 commit intoopen-telemetry:mainfrom
devilcoolyue:fix-bug-throttling-logger
Mar 3, 2025
Merged

fix bug: throttledRateLimiter is not once per minute, but five times#7156
jack-berg merged 1 commit intoopen-telemetry:mainfrom
devilcoolyue:fix-bug-throttling-logger

Conversation

@devilcoolyue
Copy link
Contributor

After I stopped the otel collector, the program injected with agnet logged errors. The error logs were printed very frequently. I saw that the source code had already limited the flow of printing logs, but it was not as expected once a minute, but still five times a minute. Then I checked the code and found that there was an error in the parameter assignment. After changing it, it ran OK.
Thanks for reviewing the PR! I appreciate your time and any feedback you can provide.
application-log.txt

@devilcoolyue devilcoolyue requested a review from a team as a code owner February 27, 2025 10:04
@linux-foundation-easycla
Copy link

linux-foundation-easycla bot commented Feb 27, 2025

CLA Signed

The committers listed above are authorized under a signed CLA.

  • ✅ login: devilcoolyue / name: tianlan xu (5a8946d)

@trask
Copy link
Member

trask commented Feb 27, 2025

hi @devilcoolyue! are you able to sign the CLA above? #7156 (comment)

@devilcoolyue
Copy link
Contributor Author

devilcoolyue commented Feb 27, 2025

hi @devilcoolyue! are you able to sign the CLA above? #7156 (comment)

hello @trask ! I just signed the CLA

@devilcoolyue devilcoolyue force-pushed the fix-bug-throttling-logger branch 2 times, most recently from bb3168d to d8c65d1 Compare February 28, 2025 01:08
@codecov
Copy link

codecov bot commented Feb 28, 2025

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 89.85%. Comparing base (313d391) to head (5a8946d).
Report is 6 commits behind head on main.

Additional details and impacted files
@@            Coverage Diff            @@
##               main    #7156   +/-   ##
=========================================
  Coverage     89.85%   89.85%           
  Complexity     6622     6622           
=========================================
  Files           740      740           
  Lines         20007    20007           
  Branches       1968     1968           
=========================================
  Hits          17978    17978           
  Misses         1439     1439           
  Partials        590      590           

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

this.throttledRateLimiter =
new RateLimiter(RATE_LIMIT / rateTimeUnit.toSeconds(1), THROTTLED_RATE_LIMIT, clock);
new RateLimiter(
THROTTLED_RATE_LIMIT / rateTimeUnit.toSeconds(1), THROTTLED_RATE_LIMIT, clock);
Copy link
Member

Choose a reason for hiding this comment

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

The throttledRateLimiter is currently accruing 5 credits / 60 seconds, with a max balance of 1 credits.

This changes it to accrue 1 credit / 60 seconds, with a max balance of 1 credits.

Meanwhile, we have fastRateLimiter set to accrue 5 credits / 60 seconds, with a max balance of 5 credits.

  • fastRateLimiter is used to determine whether to log during normal operation.
  • throttledRateLimiter is used to determine whether to log when throttled, which occurs when rate of logging exceeds fastRateLimiter.

The problem you're fixing is that throttledRateLimiter accrues credits too fast. I.e. despite the fact that it has a max balance of 1, it is still accruing new credits at a rate of 5 / 60 = .083 credits / second, or 1 credit every 12 seconds. So a noisy logger logging every 12 seconds (or more frequent) will be able to 5 logs per minute, when it should only be 1 log per minute.

Is that right? If so, could you adjust ThrottlingLoggerTest with a demonstration of how the current logic fails but this change fixes it?

cc @jkwatson who wrote this initial implementation

Copy link
Contributor

Choose a reason for hiding this comment

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

Looks like this was just a typo. Yes, agree it needs a test, which was obviously missing from the first implementation!

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes!Thank you for the clarification! I will work on adding the test case to validate this fix and submit it in the near future.

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've implemented a test that demonstrates the issue with the throttling logic:

@Test
void allowOnlyOneLogPerMinuteAfterSuppression() {
  TestClock clock = TestClock.create();
  ThrottlingLogger logger = new ThrottlingLogger(realLogger, clock);

  // Initial logs (before throttling)
  logger.log(Level.WARNING, "oh no!");
  logger.log(Level.WARNING, "oh no!");
  logger.log(Level.WARNING, "oh no!");
  logger.log(Level.WARNING, "oh no!");
  logger.log(Level.WARNING, "oh no!");

  // Trigger suppression
  logger.log(Level.WARNING, "oh no I should trigger suppression!");
  logger.log(Level.WARNING, "oh no I should be suppressed!");

  // Verify initial logs were recorded correctly
  assertThat(logs.getEvents()).hasSize(7);

  // With the current implementation (5 credits/60s), we get a log every 12 seconds
  // The fix changes it to 1 credit/60s, giving only 1 log per minute
  clock.advance(Duration.ofMillis(12_001));
  logger.log(Level.WARNING, "suppression 1");
  clock.advance(Duration.ofMillis(12_001));
  logger.log(Level.WARNING, "suppression 2");
  clock.advance(Duration.ofMillis(12_001));
  logger.log(Level.WARNING, "suppression 3");
  clock.advance(Duration.ofMillis(12_001));
  logger.log(Level.WARNING, "suppression 4");
  clock.advance(Duration.ofMillis(12_001));
  logger.log(Level.WARNING, "allowed 1");

  // With the fix, only "allowed 1" should appear in logs
  // With current implementation, all would be logged
  logs.assertDoesNotContain("suppression 1");
  logs.assertDoesNotContain("suppression 2");
  logs.assertDoesNotContain("suppression 3");
  logs.assertDoesNotContain("suppression 4");
  logs.assertContains("allowed 1");

  assertThat(logs.getEvents()).hasSize(8);
  assertThat(logs.getEvents().get(7).getMessage()).isEqualTo("allowed 1");
}
  • The current logic build failed
image
  • Build successfully after repair
image

The test confirms @jack-berg's analysis. The current throttling behavior allows a log every 12 seconds despite being throttled (5 credits/60s = 1 credit/12s). After changing to 1 credit/60s, the test passes, showing that only one log per minute is allowed after throttling kicks in.
This demonstrates exactly how the current implementation fails and how the fix resolves the issue.

@devilcoolyue devilcoolyue force-pushed the fix-bug-throttling-logger branch 2 times, most recently from f0bf985 to ae50e31 Compare March 2, 2025 14:01
@devilcoolyue devilcoolyue force-pushed the fix-bug-throttling-logger branch from ae50e31 to 5a8946d Compare March 2, 2025 14:09
Copy link
Contributor

@jkwatson jkwatson left a comment

Choose a reason for hiding this comment

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

Thanks!

@jack-berg jack-berg merged commit 16f3637 into open-telemetry:main Mar 3, 2025
27 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants