Python/Flask integration stack trace is not ALWAYS included with logger.exception

SDKs
1

Our flask app is structured as follows:

flask_app/
|--app
|--utils

in the logging config dict in the app dir BOTH the app and utils logger include an identical sentry handler. Now here is where it gets interesting. In file utils.crasher I have:

import logging

logger = getLogger(__name__)

def crash_boy():
    try:
        1 + '123'
    except Exception as e:
        logger.exception('Oh gosh we messed up big time here')
        raise e

and in app.main

@bp.route('/crash')
def crash():
    try:
        return crash_boy()
    except Exception as e:
        logger.exception('OH GREAT')
        return 'WE HAD A CRASH BOIZ'

The utils logger DOES include a traceback but the app logger will only log the string (‘OH GREAT’) with no stack trace.

After thorough testing our app logger will ONLY log an exceptions stack trace in an uncaught exception of an except block like so:

# 1/0 here would log an error and line number in sentry UI but no stack trace
try:
    1/0
except Exception as e:
    logger.exception('Probably did 1/0') # No stack trace in web UI
    1 + '1' #will include a stack trace in web UI

So it seems sentry CAN include a traceback via the app logger but only in uncaught exceptions inside an except block.

2

Hey Eric,

You’ll need to explicitly include the stack trace when logging, using the extra kwarg.

logger.exception('Probably did 1/0', extra={'stack': True})
3

@mike That still doesn’t explain why NOT setting that in the utils.crasher.py file does send an accurate stack trace. When explicitly setting the extra kwarg in app.main the new stack trace points to code in gevent/greenlet and not the ZeroDivisionError as expected.

4

additionally manually doing sentry.captureException() does report the error to sentry so there is inconsistent behavior between logger.exception('Probably did 1/0', extra={'stack': True}) and captureException in addition to the inconsistent behavior of the exception logger depending on which module it is invoked in.

5

The exception on the logger is attached by python logging. We just pick it up. About why it’s necessary in one place and not in another I cannot tell you. I have seen such things before when gevent was used.

Which Python version do you use and do you use any concurrency modules? (gevent, eventlet etc.)

6

Greetings Armin,

We are using python 2.7 with gevent workers on gunicorn.

7

@erik-farmer yeah. In that case I’m not surprised this happens. I believe it happens if a context switch happens upon error handling. I have seen this before and the best workaround I have is to do this:

try:
    ...
except Exception:
    exc_info = sys.exc_info()
    logger.error('message here', exc_info=exc_info)

It still does not solve it in all situations but lowers the risk of the traceback going away.