Bread Crumbs showing data from other uWSGI requests

[bartek]

Hi Sentry Team,

We are running a Django application, with a uWSGI config of the following (Irrelevant data snipped):

[uwsgi]
project = gapi-layer-drf

base = /var/www
home = /opt/lib/virtualenvs/%(project)
chdir = /var/www/gapi-layer-drf/gapi

pythonpath = /var/www/gapi-layer-drf/gapi
module = gapi.wsgi

plugins-dir = /opt/uwsgi/uwsgi-2.0.13.1
plugins = python35

uid = www-data
gid = www-data

harakiri = 20
# thunder-lock is basically necessary with threading. Helps deal with the "thundering herd" problem.
thunder-lock = true

# memory-report is necessary if doing stats. Proper reporting of data.
memory-report = true
logto = /var/log/uwsgi/%(project).log
logfile-chown = www-data

master = true
processes = 5
threads = 5

# Hush uWSGI from IOError, SIGPIPE, etc.
ignore-sigpipe = true
ignore-write-errors = true
disable-write-exception = true

# Setup a socket, which is more secure and offers better performance than a network port.
socket = /tmp/%(project).sock
chmod-socket = 666
chown-socket = www-data

# Use vacuum to clean up when the service is stopped.
vacuum = true

We are using Django Rest Framework and a custom Exception Handler. Essentially, any exception is captured, transformed for the response, but also delivered to Sentry via the standard logging module. We are using Raven 5.32

The Bread Crumbs seem to work well for the most part, and the tail of the crumbs indeed shows the appropriate request that caused the exception. For example. Here's the tail end of a crumb, with the exception/time:

Then, above that, I have more crumbs, that are generally hidden (but not always). The primary thing to note is the substantial time difference between the previous crumbs and these ones. Essentially, they are not part of the same request-response cycle (and knowing our system, I can confirm that. We'd never hit a booking while hitting the Flight Control backend within a single request)

So, quite an interesting bit for us. It's not necessarily an issue, but it might confuse our developers (or even myself in a pre-coffee state) what's going on with this request.

Anything else I can provide, please let me know. Happy to help. Thank you!

[dcramer]

That actually doesnt sound surprising to me. The uWSGI request/response cycle isnt a known quantity to Sentry, and we dont reset breadcrumbs at the start of a request IIRC. I'm not sure if our WSGI middleware does take care of this or not, but IIRC it doesn't (and should).

@mitsuhiko thoughts?

[bendemaree]

@dcramer Running into this as well. ISTM that under normal circumstances, process_response clears the context which should clear the breadcrumbs on the current thread. However, if an exception is raised and handle_exception is called on the middleware, would the context (and thus breadcrumbs) still get cleared? Is it as simple as clearing the context there as well?

[mitsuhiko]

@bendemaree are you running into this with django? FWIW, the ClosingIterator is responsible for clear. Not sure what process_response even was supposed to be doing. I killed that method now as it does not do anything.

Is this also happening with uwsgi or something else?

[bendemaree]

Hi @mitsuhiko! No Django; running Falcon in this case, and we're running exclusively with uWSGI.

I feel a little shy asking you in particular this, but process_response would've been called if this middleware were running under Flask, right?

I'll work on coming up with a more concise example to reproduce this.

[mitsuhiko]

@bendemaree no, that's unrelated. This is a WSGI middleware and it works the same everywhere.

[bartek]

Not sure if this is related but something to add to the issue. I am seeing this sometimes, not with every exception:

DEBUG 2016-12-08 16:57:30,697 base 48353 139996363421440 Sending message of length 2562 to https://sentry.io/api/95888/store/
/opt/lib/virtualenvs/gapi-layer-drf/lib/python3.5/site-packages/raven/utils/compat.py:59: Warning: We detected the use of uwsgi with disabled threads.  This will cause issues with the transport you are trying to use.  Please enable threading for uwsgi.  (Enable the "enable-threads" flag).
  warn(Warning('We detected the use of uwsgi with disabled threads.  '
WARNING 2016-12-08 16:57:30,516 exception_handler 48353 139996363421440 Date fields must be formatted as YYYY-MM-DD

But as shared above, my uWSGI config has threads = 5. So perhaps this is something else?

[mattrobenolt]

But as shared above, my uWSGI config has threads = 5. So perhaps this is something else?

fwiw enable-threads is different from threads. threads is how many uWSGI threads to run to process requests, but enable-threads is to enable the use of the GIL and allow application layer threads in Python. This is important from raven-python since we'd prefer to use a thread to send our messages and not block the running application.

[mitsuhiko]

I tried to blast a few requests locally to it and it always gets the thread information right. There must be more to this story. Are you using eventlet or greenlet?

[bartek]

@mattrobenolt Hm, thanks. I will adjust my uWSGI configuration to have that turned on. From your experience, does this impact Django/Flask/etc. in any way?

@mitsuhiko I am not using eventlet or greenlet. Not sure what else to provide outside of my uWSGI config, so any ideas, I'm all ears. Would be happy to share more.

[mitsuhiko]

@bartek enable-threads should be the default same as with the holy mode. uWSGI does some weird thing to cheap in benchmarks but that causes various issues. Our docs point out to enable that I think.

[bartek]

@mattrobenolt As a followup to your comment, I did review the uWSGI docs and identified this paragraph -- I recall seeing this when I was investigating threads

By default the Python plugin does not initialize the GIL. This means your app-generated threads will not run. If you need threads, remember to enable them with enable-threads. Running uWSGI in multithreading mode (with the threads options) will automatically enable threading support.

However, Raven does complain about the lack of enabled threads so ... confusing. Not sure which documentation to trust anymore ;)

[mitsuhiko]

This was also reported to happen with non django (it was reported for flask).

[mitsuhiko]

My guess currently is that this might happen if multiple clients are involved and a client's is active for the wrong thread.

[mattrobenolt]

However, Raven does complain about the lack of enabled threads so ... confusing. Not sure which documentation to trust anymore ;)

Ah, I'll have to review. We might have to change our check. We are explicitly checking for enable-threads, but if that's true, we can check for either option.

[mattrobenolt]

@bartek see: https://github.com/getsentry/raven-python/pull/928 I verified this is true locally.

[bartek]

@mattrobenolt Ah great! So perhaps that was simply a red herring :)

My guess currently is that this might happen if multiple clients are involved and a client's is active for the wrong thread.

@mitsuhiko When you say client, you are specifically speaking of any arbitrary client making the HTTP request, correct? We do have many requests occurring at once, but they shouldn't be stepping over each others toes in any way, since they all have explicit requests and actions. Hmm.

[mattrobenolt]

When you say client, you are specifically speaking of any arbitrary client making the HTTP request, correct?

No, we mean instances of the Raven client.

[antdking]

We're getting the same issue with Django + gunicorn. Breadcrumbs work as expected when using the debug server.

gunicorn config for testing:

import os
# assumes gunicorn conf is located 1 directory inside root. change appropriately (app_root/configs/)
config_dir = os.path.dirname(os.path.realpath(__file__))
chdir = os.path.dirname(config_dir)
bind = '127.0.0.1:8000'
timeout = 120

[jonashaag]

Same problem here with Django and --enable-threads. The rest of our setup is a pretty vanilla Django one. How can I help debug this?

[jan11011977]

Apologies if this is not relevant, but for me this issue seems to go away when I remove the following lines of code:

https://github.com/getsentry/raven-python/blob/master/raven/context.py#L129-L135

[danpalmer]

Hey, would be good to get an update on this. We've just started trialling Sentry, and this is causing breadcrumbs to be pretty useless.

We're Python 3, Django, gunicorn running worker processes, installed just with the app in INSTALLED_APPS (i.e. we aren't using the WSGI middleware). Happy to provide more info to debug this.

[mitsuhiko]

@danpalmer gunicorn is a different issue. If you are using gunicorn i don't think breadcrumbs work properly yet unless something patches threading.local. Not sure if gunicorn does that.

[akx]

I'm also seeing what seem to be breadcrumbs from irrelevant requests on uWSGI (only noticed it now even if we've been using Sentry for a while 😅 ).

Since our uwsgi.ini looks like follows (plus some irrelevant stanzas), each worker should only be dealing with a single request at a time. We do have some "worker" threads that shoot stuff into metrics services and so on, but those shouldn't matter...

[uwsgi]
die-on-term
enable-threads
master
need-app
strict
thunder-lock
wsgi = roi.wsgi
http = :8000
processes = 16
cheaper = 4
max-requests = 1000
offload-threads = 4
reload-on-rss = 1000

[akx]

Hmm, if it helps, it looks like these leaky breadcrumbs maybe don't occur for exceptions, only for logging output. Our logging config is (non-Raven/Sentry things cropped out)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'root': {
        'level': 'INFO',
        'handlers': ['sentry'],
    },
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
    },
    'handlers': {
        'sentry': {
            'level': 'WARNING',
            'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
            'filters': ['require_debug_false'],
        },
    },
    'loggers': {
        'raven': {
            'level': 'WARNING',
            'handlers': ['console'],
            'propagate': False,
        },
        'sentry.errors': {
            'level': 'DEBUG',
            'handlers': ['console'],
            'propagate': False,
        },
    }
}