Skip to content
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.

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

Traceback missing #173

Closed
md1023 opened this issue Jul 6, 2018 · 17 comments

Comments

@md1023
Copy link

@md1023 md1023 commented Jul 6, 2018

My Django 1.8, Python 2 application uses third party middleware:

import struct
logger = structlog.get_logger(__name__)

class MyMiddleware(AuthMiddleware):
    def process_view(self, *args, **kwargs):
        print('FOO')
        1/0
        return super(MyMiddleware, self).process_view(*args, **kwargs)

My output misses tracebacks:

FOO
2018-07-06 11:06.36 {'events': []}

I can't debug, even see errors!

I did try zero-config options, other configuration options, structlog.processors.ExceptionPrettyPrinter(), but couldn't find who swallows and exception. I looked for try/excepts with pass, but there's not one for 1/0.

Please suggest some idea, I'm running out of debug options.

@md1023

This comment has been minimized.

Copy link
Author

@md1023 md1023 commented Jul 6, 2018

I forgot Django does some 'magic' and captures logs.

I put extra logger:

    'loggers': {
        '': {
            'handlers': ['colored_console'],
            'level': 'WARNING',
        },
        'django': {
            'handlers': ['colored_console'],
            'level': 'WARNING',
        },

To my excitement, exceptions did appear. Unfortunately not expected ones:

  File "/usr/local/lib/python2.7/site-packages/oauthlib/oauth2/rfc6749/grant_types/resource_owner_password_credentials.py", line 101, in create_token_response
    if not self.request_validator.authenticate_client(request):
  File "./my_server/oauth2/validators.py", line 151, in authenticate_client
    logger.exception(exc)
  File "/usr/local/lib/python2.7/site-packages/structlog/_base.py", line 176, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
  File "/usr/local/lib/python2.7/site-packages/structlog/_base.py", line 136, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
  File "/usr/local/lib/python2.7/site-packages/structlog/dev.py", line 191, in __call__
    event += self._styles.reset
TypeError: unsupported operand type(s) for +=: 'exceptions.TypeError' and 'str'

This time I intentionally didn't run structlog.configure, relying on default configuration.

Along with this issue, could I drop 'django' from loggers and still get exceptions?

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Jul 6, 2018

A TypeError for 1/0 looks wrong too, so I suspect there’s something else going on.

But first things first. Given the error message it looks like it’s trying to render a TypeError as a string. That suggests that you have neither structlog.processors.ExceptionPrettyPrinter nor structlog.processors.format_exc_info in your chain. Does adding them change the error at all?

@md1023

This comment has been minimized.

Copy link
Author

@md1023 md1023 commented Jul 6, 2018

Definitely something else.

Here's my django settings.py snippet:

LOGGING = {
    ...
}

import structlog
from pprint import pprint
structlog.reset_defaults()
pprint(structlog.get_config())

Here's server start:

root@my-server:/opt/my_server/server# docker-entrypoint.sh run_uwsgi
+ case "$1" in
+ collect_static
+ python manage.py collectstatic --noinput
{'cache_logger_on_first_use': False,
 'context_class': <class 'collections.OrderedDict'>,
 'logger_factory': <structlog._loggers.PrintLoggerFactory object at 0x7f918c819c90>,
 'processors': [<structlog.processors.StackInfoRenderer object at 0x7f918c8199d0>,
                <function format_exc_info at 0x7f918cc78d70>,
                <structlog.processors.TimeStamper object at 0x7f918c819a50>,
                <structlog.dev.ConsoleRenderer object at 0x7f918c819a90>],
 'wrapper_class': <class 'structlog._generic.BoundLogger'>}

0 static files copied to '/opt/my_server/server/static', 30 unmodified.
+ run_uwsgi_server

format_exc_info's in place by default. I tried to interchange them but it didn't help.

I'm stuck with legacy versions right now. django.request logs 1/0 but not in the way I'd like. Hopefully I'll find something.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Jul 6, 2018

Wait, I see your problem: logger.exception(exc) is wrong both in structlog and in logging – that explains the other exception. In structlog it would be logger.exception("something_went_wrong", exception=exc). If it's within an except block, it’s just logger.exception("something_went_wrong").

@md1023

This comment has been minimized.

Copy link
Author

@md1023 md1023 commented Jul 6, 2018

But this code runs validly in Python 2.7.15:

# zzz.py
import logging
import logging.config

logging.basicConfig(level='DEBUG')
logger = logging.getLogger(__name__)

try:
    1/0
except ZeroDivisionError as exc:
    logger.exception(exc)
    print '\n--- newline ---\n'
    raise AttributeError('attribute error')

And result is:

> python zzz.py
ERROR:__main__:integer division or modulo by zero
Traceback (most recent call last):
  File "zzz.py", line 8, in <module>
    1/0
ZeroDivisionError: integer division or modulo by zero

 --- newline ---

Traceback (most recent call last):
  File "zzz.py", line 12, in <module>
    raise AttributeError('attribute error')
AttributeError: attribute error

Part of my refactor was to unhide passed try/except block exceptions and logger.exception(exc) did the job. But looks like it introduced more trouble than I wanted before we implemented structlog.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Jul 6, 2018

The official signature for logger.exception is:

Logger.exception(msg, *args, **kwargs)

Logs a message with level ERROR on this logger. The arguments are interpreted as for debug(), except that any passed exc_info is not inspected. Exception info is always added to the logging message. This method should only be called from an exception handler.

So it’s weird that it actually worked. I suspect that your “msg” just got swallowed inside of logging because it couldn’t get formatted and worked only by accident.

Try this: if you replace exc by None in your call to logging.exception() you get the same output.

This is one of the reasons why structlog is a lot more pedantic about this kind of stuff – wrong code that works by accident is very painful to debug.

@md1023

This comment has been minimized.

Copy link
Author

@md1023 md1023 commented Jul 6, 2018

I came up with final question. Please, consider zzz.py:

import logging
import logging.config

import structlog

# Uncomment one of following
# the_logging = structlog
# the_logging = logging

logging.basicConfig(level='DEBUG')
logger = the_logging.getLogger(__name__)

try:
    1/0
except ZeroDivisionError as exc:
    logger.exception('logged exception')
    print '\n--- newline ---\n'
    raise AttributeError('attribute error')

Example without expected traceback:

python /tmp/zzz.py
2018-07-06 17:05.50 logged exception

--- newline <module 'structlog' from '/tmp/venv/local/lib/python2.7/site-packages/structlog/__init__.pyc'> ---

Traceback (most recent call last):
  File "/tmp/zzz.py", line 17, in <module>
    raise AttributeError('attribute error')
AttributeError: attribute error

Example with expected traceback:

(venv) > python /tmp/zzz.py
ERROR:__main__:logged exception
Traceback (most recent call last):
  File "/tmp/zzz.py", line 13, in <module>
    1/0
ZeroDivisionError: integer division or modulo by zero

--- newline <module 'logging' from '/usr/lib/python2.7/logging/__init__.pyc'> ---

Traceback (most recent call last):
  File "/tmp/zzz.py", line 17, in <module>
    raise AttributeError('attribute error')
AttributeError: attribute error

How do I get same result for structlog case? I thought I'd see dict with exception key, but I don't see it.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Jul 6, 2018

Oh, that’s an interesting one!

I think the problem here is that the default PrintLogger doesn’t look for exceptions: https://github.com/hynek/structlog/blob/master/src/structlog/_loggers.py#L80

Install colorama and add the following:

structlog.configure(
    processors=[
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S"),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeEncoder(),
        structlog.dev.ConsoleRenderer(),
    ],
    wrapper_class=structlog.stdlib.BoundLogger,
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=False,
)

The default behavior is clearly poorly chosen here (and I haven’t noticed because I don’t use them) – I’ll have a closer look at PrintLogger.

@md1023

This comment has been minimized.

Copy link
Author

@md1023 md1023 commented Jul 6, 2018

Thank you, Hynek. I've just run first barrage of tests successfully. Hope won't bother you next week. Bye!

@md1023 md1023 closed this Jul 6, 2018
@AndydeCleyre

This comment has been minimized.

Copy link
Contributor

@AndydeCleyre AndydeCleyre commented Mar 22, 2019

So to clarify, is the following behavior a bug (and if so, is it a new bug)?

In [1]: import structlog                                                
                                                                        
In [2]: log = structlog.get_logger()                                    
                                                                        
In [3]: try:                                                            
   ...:     1/0
   ...: except Exception as e:
   ...:     log.msg('uh oh', exc_info=e)                               
   ...: 
2019-03-21 21:03.32 uh oh                         
Traceback (most recent call last):
  File "<ipython-input-3-26d5f9da34af>", line 2, in <module>
    1/0
ZeroDivisionError: division by zero
In [1]: import structlog

In [2]: structlog.configure(processors=[structlog.processors.format_exc_
   ...: info, structlog.dev.ConsoleRenderer()])

In [3]: log = structlog.get_logger()

In [4]: try:
   ...:     1/0
   ...: except Exception as e:
   ...:     log.msg('uh oh', exc_info=e)
   ...: 
uh oh                          
Traceback (most recent call last):
  File "<ipython-input-4-26d5f9da34af>", line 2, in <module>
    1/0
ZeroDivisionError: division by zero

structlog 19.1.0
Python 3.7.2

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 22, 2019

No, that's expected behavior. What appears buggy about that to you?

OP's problem was that he'd rightfully expect that a bare log.exception sets exc_info for him.

See also the recent #200 which looks related.

@AndydeCleyre

This comment has been minimized.

Copy link
Contributor

@AndydeCleyre AndydeCleyre commented Mar 22, 2019

What appears buggy about that to you?

According to the docs:

Default [processor chain] is [format_exc_info(), KeyValueRenderer].

and according to the docs, the effect of that processor is to

Replace an exc_info field by an exception string field

But in those two examples, the exc_info field is dropped while no exception field is added.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 22, 2019

That looks like a bug in the docs! The default has been ConsoleRenderer for three years now: https://github.com/hynek/structlog/blame/master/src/structlog/_config.py#L27

And ConsoleRenderer pops off the exception and prints it after the log line for readability. It's intended for human consumption after all.

Where is the quote from?

@AndydeCleyre

This comment has been minimized.

Copy link
Contributor

@AndydeCleyre AndydeCleyre commented Mar 22, 2019

http://www.structlog.org/en/stable/loggers.html lists the default processors as:

[format_exc_info(), KeyValueRenderer]

indicating that exc_info will turn into exception.

http://www.structlog.org/en/stable/_modules/structlog/_config.html shows:

_BUILTIN_DEFAULT_PROCESSORS = [
    StackInfoRenderer(),
    format_exc_info,
    TimeStamper(fmt="%Y-%m-%d %H:%M.%S", utc=False),
    ConsoleRenderer(colors=_has_colorama),
]

indicating that exc_info will turn into exception.

http://www.structlog.org/en/stable/_modules/structlog/processors.html includes:

def format_exc_info(logger, name, event_dict):
    """
    Replace an `exc_info` field by an `exception` string field:

    If *event_dict* contains the key ``exc_info``, there are two possible
    behaviors:

    - If the value is a tuple, render it into the key ``exception``.
    - If the value is an Exception *and* you're running Python 3, render it
      into the key ``exception``.
    - If the value true but no tuple, obtain exc_info ourselves and render
      that.

    If there is no ``exc_info`` key, the *event_dict* is not touched.
    This behavior is analogue to the one of the stdlib's logging.
    """

indicating that exc_info will turn into exception.

http://www.structlog.org/en/stable/api.html includes:

 structlog.processors.format_exc_info(logger, name, event_dict)

    Replace an exc_info field by an exception string field:

    If event_dict contains the key exc_info, there are two possible behaviors:

        - If the value is a tuple, render it into the key exception.
        - If the value is an Exception and you’re running Python 3, render it into the key exception.
        - If the value true but no tuple, obtain exc_info ourselves and render that.

    If there is no exc_info key, the event_dict is not touched. This behavior is analogue to the one of the stdlib’s logging.

indicating that exc_info will turn into exception.

http://www.structlog.org/en/stable/_modules/structlog/dev.html includes:

class ConsoleRenderer(object):
    """
    Render `event_dict` nicely aligned, possibly in colors, and ordered.

    :param int pad_event: Pad the event to this many characters.
    :param bool colors: Use colors for a nicer output.
    :param bool force_colors: Force colors even for non-tty destinations.
        Use this option if your logs are stored in a file that is meant
        to be streamed to the console.
    :param bool repr_native_str: When ``True``, :func:`repr()` is also applied
        to native strings (i.e. unicode on Python 3 and bytes on Python 2).
        Setting this to ``False`` is useful if you want to have human-readable
        non-ASCII output on Python 2.  The `event` key is *never*
        :func:`repr()` -ed.
    :param dict level_styles: When present, use these styles for colors. This
        must be a dict from level names (strings) to colorama styles. The
        default can be obtained by calling
        :meth:`ConsoleRenderer.get_default_level_styles`

    Requires the colorama_ package if *colors* is ``True``.

    .. _colorama: https://pypi.org/project/colorama/

    .. versionadded:: 16.0
    .. versionadded:: 16.1 *colors*
    .. versionadded:: 17.1 *repr_native_str*
    .. versionadded:: 18.1 *force_colors*
    .. versionadded:: 18.1 *level_styles*
    """

which doesn't mention any exceptional handling of exc_info.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 22, 2019

Yes, it's totally a documentation fail. I have fixed it in cc063e0

You can check the rendered version at:

Is this satisfying to you?

@AndydeCleyre

This comment has been minimized.

Copy link
Contributor

@AndydeCleyre AndydeCleyre commented Mar 22, 2019

Thank you, the doc changes are very good and in the right places. Sorry for piggy-backing on this issue. Though it may confusing that you listed the default processors as

[StackInfoRenderer, format_exc_info(), TimeStamper, ConsoleRenderer]

when they need to be passed as

[StackInfoRenderer(), format_exc_info, TimeStamper(), ConsoleRenderer()]

I notice at http://www.structlog.org/en/latest/configuration.html it says that

. . . PrintLogger is the default LoggerFactory used

Is that still true?

I do think it would be helpful to add to the Getting Started page an expansion of the default configuration. Right after the link to the configuration docs, just before the note about using KeyValueRenderer for brevity. Something like:

Using the defaults, as above, is equivalent to:

.. code:: python

  import structlog
  structlog.configure(processors=[
      structlog.processors.StackInfoRenderer(),
      structlog.processors.format_exc_info,
      structlog.processors.TimeStamper(),
      structlog.dev.ConsoleRenderer()
  ])
  log = structlog.get_logger()

Thanks for your continued development of structlog, the sanest Python logging tool around.

@hynek

This comment has been minimized.

Copy link
Owner

@hynek hynek commented Mar 22, 2019

Is that still true?

Yep!

Would you mind open a new issue for the getting started part? I'm always interested in making structlog more approachable but this is getting hard to track.

Thanks for your continued development of structlog, the sanest Python logging tool around.

Thank you, I appreciate that!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.