evalphobia / logrus_sentry

sentry hook for logrus
MIT License
194 stars 78 forks source link

Stop double-buffering in async hook #47

Closed glasser closed 7 years ago

glasser commented 7 years ago

The underlying Raven Sentry client already is asynchronous with an adjustable buffer size. Unlike the buffer in logrus_sentry, Raven drops packets when the buffer is filled (and calls an optional DropHandler when it does so).

The existing implementation of async hooks does not drop packets when its buffer fills, which means that the so-called "async" hook becomes synchronous if the buffer fills, and the Raven packet-dropping logic most likely never has a chance to do its tricks. In our service, we discovered that bugs that caused errors to spew to Sentry via logrus_sentry quickly hit this buffer's limit and caused our service to stall, despite the supposedly "async" nature of the hook.

This commit changes logrus_sentry's async mode to be truly asynchronous: it delivers packets to Raven, which either passes them to its background worker or drops them if its buffer is full. It then starts a new goroutine per packet to log any errors and coordinate with the WaitGroup for flush.

The previous version of the code set a 1 second Timeout for async mode, which effectively just allowed the worker goroutine to send the next packet to Raven after 1 second. Because we no longer have a separate worker goroutine, this is no longer necessary. A comment also mentions how to set a timeout for the underlying HTTP POST, which achieves a similar goal of allowing Flush to finish in a bounded amount of time.

Note that Raven's buffer size (100) is smaller than logrus_sentry's old buffer size (8192), so users may want to increase raven.MaxQueueBuffer before contructing the hook to avoid dropping packets.

coveralls commented 7 years ago

Coverage Status

Coverage increased (+0.2%) to 83.944% when pulling ddacc000a2cd69d8d50ae248ebf45d279273fdd6 on meteor:glasser/simpler-async into 7c1b7faba7ed5772effc03db8e1faa8c90624660 on evalphobia:master.

glasser commented 7 years ago

@flimzy Thought you might want to see this as you implemented async mode.

coveralls commented 7 years ago

Coverage Status

Coverage increased (+2.0%) to 85.714% when pulling 23239492feda0d8547bc36080b1d439fd4817cc5 on meteor:glasser/simpler-async into 7c1b7faba7ed5772effc03db8e1faa8c90624660 on evalphobia:master.

coveralls commented 7 years ago

Coverage Status

Coverage decreased (-0.3%) to 83.473% when pulling 23239492feda0d8547bc36080b1d439fd4817cc5 on meteor:glasser/simpler-async into 7c1b7faba7ed5772effc03db8e1faa8c90624660 on evalphobia:master.

glasser commented 7 years ago

I'm finding it difficult to parse the coveralls output, but I don't think I actually made anything less covered — I just think I rewrote enough code to change the ratio a little.

evalphobia commented 7 years ago

Cool!

Note: https://github.com/evalphobia/logrus_sentry/releases/tag/v0.4.0