Skip to content

fix: Enforce max queue length in transport #593

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 3 commits into from
Jan 21, 2020
Merged

fix: Enforce max queue length in transport #593

merged 3 commits into from
Jan 21, 2020

Conversation

untitaker
Copy link
Member

@untitaker untitaker commented Jan 17, 2020 •
edited
Loading

fix #586

@untitaker untitaker force-pushed the fix/max-queue-items branch from 05b62e8 to 51dccfc Compare January 17, 2020 14:15
@untitaker untitaker requested a review from mitsuhiko January 17, 2020 14:15
untitaker
untitaker commented Jan 17, 2020
View reviewed changes
sentry_sdk/worker.py Outdated
@@ -89,7 +89,7 @@ def kill(self):
logger.debug("background worker got kill request")
with self._lock:
if self._thread:
self._queue.put_nowait(_TERMINATOR)
self._queue.put(_TERMINATOR)
Copy link
Member Author

Choose a reason for hiding this comment

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

Not sure about this part. I think it's legit to block a little more on flush/close, even beyond the timeout, if the queue is completely full.

Copy link
Contributor

Choose a reason for hiding this comment

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

(sorry, fat fingered the resolve button on my phone)

Other SDKs have a timeout on operations like this. Is kill used like "close"?

Copy link
Member Author

Choose a reason for hiding this comment

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

kill is an internal method that is supposed to be nonblocking. close calls flush with a timeout and then kill. I will actually revert this change for now.

@untitaker untitaker requested a review from rhcarvalho January 20, 2020 21:05
@rhcarvalho
Copy link
Contributor

Running some tests locally 👀

rhcarvalho
rhcarvalho approved these changes Jan 21, 2020
View reviewed changes
Copy link
Contributor

@rhcarvalho rhcarvalho left a comment

Choose a reason for hiding this comment

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

Works as intended! 🎉

As a side-effect, now transport.kill may raise queue.Full under special circumstances. We may or may not handle that, will leave it up to you.

sentry_sdk/worker.py
try:
self._queue.put_nowait(callback)
except queue.Full:
logger.debug("background worker queue full, dropping event")
Copy link
Contributor

Choose a reason for hiding this comment

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

Tested by sending loads of events in a row. This seems to be working as intended.

In a given run, out of 106 events created in a loop, the client dropped 76 and the server received 30.

import os

from sentry_sdk import init, capture_message, flush


init(debug=True)

for i in range(int(os.environ["TEST_N"])):
    capture_message("hello")

flush()
Running tool: /usr/bin/go test -benchmem -run=^$ github.com/getsentry/sentry-go/internal/testing/external -bench ^(Benchmark)$

goos: linux
goarch: amd64
pkg: github.com/getsentry/sentry-go/internal/testing/external
Benchmark-8   	--- FAIL: Benchmark-8
    /home/rodolfo/sentry/sentry-go/internal/testing/external/external_test.go:56: counter = 30, want 106
        out:
         [sentry] DEBUG: Setting up integrations (with default = True)
         [sentry] DEBUG: Setting up previously not enabled integration logging
         [sentry] DEBUG: Setting up previously not enabled integration stdlib
         [sentry] DEBUG: Setting up previously not enabled integration excepthook
         [sentry] DEBUG: Setting up previously not enabled integration dedupe
         [sentry] DEBUG: Setting up previously not enabled integration atexit
         [sentry] DEBUG: Setting up previously not enabled integration modules
         [sentry] DEBUG: Setting up previously not enabled integration argv
         [sentry] DEBUG: Setting up previously not enabled integration threading
         [sentry] DEBUG: Enabling integration logging
         [sentry] DEBUG: Enabling integration stdlib
         [sentry] DEBUG: Enabling integration excepthook
         [sentry] DEBUG: Enabling integration dedupe
         [sentry] DEBUG: Enabling integration atexit
         [sentry] DEBUG: Enabling integration modules
         [sentry] DEBUG: Enabling integration argv
         [sentry] DEBUG: Enabling integration threading
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: background worker queue full, dropping event
         [sentry] DEBUG: Flushing HTTP transport
         [sentry] DEBUG: background worker got flush request
         [sentry] DEBUG: Sending event, type:null level:info event_id:09e8335bce0649c09da7656ad68075d2 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:b174e0d0d20c4a9db8333dfbe0c3d1a4 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:cfefb573eec044b1ae70e85c48aa52e3 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:80692ebf568d401e8ea5268f58640632 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:f5c39ade2323471bac4cb74786e97d3a project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:d08bdc0cc4ef4424b27ab3ca14de7ca4 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:61399f8daf914a27bee67dab24fcd05d project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:e00909b9d7f1462f933dc125eb004d9c project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:0c4375b1274349e3b3775b2a3ba17b63 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:de9fb90825664d9ab49c674c5e3087ac project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:de899ab160a74dd79e0bb1abfb6441e3 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:d4554cca8a6143119f206ad17f53995e project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:9b95b26ddf55476a8efb6a09bd27e256 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:6eda2eba4b754545b25e97b55ad1be27 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:3339ec53ee764051b877f1b35513a187 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:43ac680fa32348f3a8f78a47f63c256e project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:81208ad7342848c898c57fab54b7d10e project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:149acb3e77f84698b2912c061517b5b9 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:80c52b4d76064afa811b5dfad7e94868 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:e80986ed68b34e78ba0ecb04fce564d0 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:6888ec59e9404940b1839f2dcbcba2de project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:9bdbe6516be04a1c9d983d42f6368a3a project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:56b7bb41e0df4f0abf4d77251750f7ef project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:3fab2769c26a44f4a2cfe5ffb3665e5c project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:e0af922a3f4747be9e3384ce7dabf717 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:2d587d0bb3404b6f89e41d75755f9094 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:49521350105445fc8934eec238ec5b18 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:a58be743dc3c40109d4e5534c986fc18 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:a7263a814084424c8d08ec315a6aa895 project:42 host:127.0.0.1
         [sentry] DEBUG: Sending event, type:null level:info event_id:0c56442964054efdb746562aedb2d7ee project:42 host:127.0.0.1
         [sentry] DEBUG: background worker flushed
         [sentry] DEBUG: atexit: got shutdown signal
         [sentry] DEBUG: atexit: shutting down client
         [sentry] DEBUG: Flushing HTTP transport
         [sentry] DEBUG: background worker got flush request
         [sentry] DEBUG: background worker flushed
         [sentry] DEBUG: Killing HTTP transport
         [sentry] DEBUG: background worker got kill request

sentry_sdk/worker.py
"""
Kill worker thread. Returns immediately. Not useful for
waiting on shutdown for events, use `flush` for that.
"""
Copy link
Contributor

Choose a reason for hiding this comment

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

In theory now kill may raise queue.Full.

I'll consider people should never call this directly, but instead use Hub.current.client.close(), which does:

           self.flush(timeout=timeout, callback=callback)
           self.transport.kill()

The first flush should empty the queue (may not empty if the timeout is reached), then transport.kill() should be able to put the _TERMINATOR.

Since there are some "shoulds", how about we handle queue.Full explicitly? In that case we can log a debug message. I don't see a clear way out without changing the current termination mechanism.

Thoughts?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah I did the same thing as with the other put_nowait now

sentry_sdk/worker.py
@@ -22,7 +22,7 @@ class BackgroundWorker(object):
def __init__(self):
# type: () -> None
check_thread_support()
self._queue = queue.Queue(-1) # type: Queue[Any]
self._queue = queue.Queue(30) # type: Queue[Any]
Copy link
Contributor

Choose a reason for hiding this comment

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

👍

@untitaker untitaker force-pushed the fix/max-queue-items branch from e6eec9c to 80e69fa Compare January 21, 2020 12:05
@untitaker
Copy link
Member Author

Thanks!

@untitaker untitaker merged commit 20fdcf1 into master Jan 21, 2020
@untitaker untitaker deleted the fix/max-queue-items branch January 21, 2020 17:08
@untitaker
Copy link
Member Author

untitaker commented Jan 21, 2020 •
edited
Loading

CI errors are unrelated to this PR

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@rhcarvalho rhcarvalho rhcarvalho approved these changes

@mitsuhiko mitsuhiko Awaiting requested review from mitsuhiko

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Memory leak introduced in 0.12.3
2 participants
@untitaker @rhcarvalho