Large numbers of exceptions are logged at ERROR level when rate limited

[adrian-baker]

Upon upgrading from the older raven-java sdk to sentry-logback: 1.6.7, we're getting a huge amount of internal exceptions logged by sentry's rate limiting implementation (an average of 1 / sec on a single JVM, see attached log).

Setting the io.sentry.SentryClient.lockdown logger to ERROR level hasn't helped.

• we would expect to never see exceptions logged from rate limiting at levels above DEBUG, so the issue isn't just one of frequency - rate limiting shouldn't result in exceptions cluttering the log, as this is just an internal detail of sentry's rate limiting implementation.
• anything that is logged shouldn't be at the ERROR level
• we can't simply disable the logger being used ("io.sentry.connection.AbstractConnection"), as it would mean we would miss genuine connectivity issues with sentry.
• the rate limiting itself is not the issue, nor is it new, however previously these were simply reported periodically as one line warnings, which worked well.

[bretthoerner]

however previously these were simply reported periodically as one line warnings

Do you mind clarifying this, because I'm trying to reconcile it with:

we would expect to never see exceptions logged from rate limiting at levels above DEBUG

I agree with the most of the rest. I think we should probably (only in the case of rate limiting responses):

• emit warnings, not errors
• leave out the stack trace
• use the lockdown (or other) logger so users can disable even the initial message

[adrian-baker]

Do you mind clarifying this

Sure: I'm just distinguishing between logging exception stack traces vs just warning messages.

For example, this is fine:

2018-02-22 09:39:07.245 WARN [sentry-pool-2-thread-15] io.sentry.SentryClient.ratelimt - Events are being rate limited

This isn't so good:

2018-02-22 09:39:07.245 WARN[sentry-pool-2-thread-15]  io.sentry.connection.AsyncConnection - An exception occurred while sending the event to Sentry.
io.sentry.connection.ConnectionException: {"error_name":"rate_limit","error":"Creation of this event was denied due to rate limiting"}
	at io.sentry.connection.HttpConnection.doSend(HttpConnection.java:192)
	at io.sentry.connection.AbstractConnection.send(AbstractConnection.java:71)
	at io.sentry.connection.AsyncConnection$EventSubmitter.run(AsyncConnection.java:173)
	at io.sentry.connection.HttpConnection.doSend(HttpConnection.java:157)

But I think you've covered this with this point:

• leave out the stack trace

[bretthoerner]

@adrian-baker I pushed up #560 if you have a chance to review?

I spammed Sentry and this was the (new) result:

10:19:08.665 [sentry-pool-1-thread-2] WARN  io.sentry.SentryClient.lockdown - Too many requests to Sentry, backing off by temporarily locking down the connection. See: https://docs.sentry.io/learn/quotas/
Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.696 [sentry-pool-1-thread-3] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.746 [sentry-pool-1-thread-1] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.796 [sentry-pool-1-thread-2] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.847 [sentry-pool-1-thread-3] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.897 [sentry-pool-1-thread-4] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.947 [sentry-pool-1-thread-1] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:08.998 [sentry-pool-1-thread-2] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.048 [sentry-pool-1-thread-3] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.099 [sentry-pool-1-thread-4] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.149 [sentry-pool-1-thread-1] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.200 [sentry-pool-1-thread-2] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.250 [sentry-pool-1-thread-3] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.300 [sentry-pool-1-thread-4] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.351 [sentry-pool-1-thread-1] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}
10:19:09.401 [sentry-pool-1-thread-2] WARN  io.sentry.SentryClient.lockdown - Dropping an Event due to lockdown: Event{level=ERROR, message='foo', logger='null'}

[bretthoerner]

This went out with 1.7.0, let me know if you continue to have any issues and thanks for reporting the issue. 😄