Especially within frameworks, one hasn’t always the power to control every part of logging.

For Twisted, there is already a solution in place, there should be also one for stdlib.

When ._proxy_to_logger is called, Python's built-in logging calls makeRecord that computes attributes that might be useful for some use cases (the most common example being filename/module and line number)

All of that information is available in ProcessorFormatter's .format at which structlog just copies the msg attribute (event_dict) and drops the rest.

My proposal is to allow copying attributes from LogRecord into the event_dict

EDIT: See https://github.com/hynek/structlog/issues/253#issuecomment-605638088 for a better idea

Roughly, that would look like

class ProcessorFormatter(logging.Formatter):

    def __init__(self, ..., copy_logrecord_attrs: Tuple[str] = ()):
        ...
        self.copy_logrecord_attrs = copy_logrecord_attrs

    def format(self, record):
        record = logging.makeLogRecord(record.__dict__)
        try:
            ...
            ed = {attr: getattr(record, attr, '?') for attr in self.copy_logrecord_attrs}
            ed.update(**record.msg.copy())
        except AttributeError:
            ...

Here, I am assuming

1. It is better to allow values from attached processors to take precedence over copying from LogRecord
2. The user of the library understands what attributes when copied are serializable

Would love to hear your thoughts on this and if it's acceptable I can send a PR too.

EDIT: After studying the code a bit more, I realized that I can get those LogRecord attributes rendered simply by passing a custom format using fmt keyword arg, but that would mean losing the niceties of using JSONRenderer

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.

First off, I’m terribly sorry I didn’t get around it any sooner. However given how long it took me to dive back into logging, I guess my procrastination was warranted. :(

Anyhow, @insolite, and @if-fi I’d like your feedback on what I’ve molded based on your PR and comments. Does this solve your problem? I’ve tried to make it more useful by adding the possibility to run stdlib entries through a separate chain, does that make sense to you?

I hope we’ll be able to close these PRs/issues soon.

Again: sorry.

This PR addresses #19. It's a rebased version of PR#29 by @lakshmi-kannan on top of current master, with additional commits by me that hopefully address all the points raised by @hynek in the review of #29.

Hi.

I couldn't find a simple example of setting a logging level properly for the whole application. This is something which turned out to be non-trivial.

If I used wrap at the top level, the loggers for modules would still use PrintLogger, and the logger which has level defined wouldn't be picked up by submodules. The only way I could make it work is to pass a factory to a structlog.config.

Is there a canonical/easy way out ?

Trying to setup structlog after it has already logged a message can put it into a strange state where logging messages causes exceptions.

import structlog
log = structlog.get_logger()
log.msg('greeted', whom='world', more_than_a_string=[1, 2, 3])

from structlog import get_logger, configure
configure(
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    # Setup logger output format.
    processors=[
        structlog.stdlib.filter_by_level,
        structlog.processors.format_exc_info,
    ])

log.warn("Hey, this isn't cool")

Output:

whom='world' more_than_a_string=[1, 2, 3] event='greeted'
Traceback (most recent call last):
  File "main.py", line 15, in <module>
    log.warn("Hey, this isn't cool")
  File "/home/ethan/Jobs/Mozilla/tmp/structlog-bug/.venv/lib/python2.7/site-packages/structlog/stdlib.py", line 73, in warning
    return self._proxy_to_logger('warning', event, *args, **kw)
  File "/home/ethan/Jobs/Mozilla/tmp/structlog-bug/.venv/lib/python2.7/site-packages/structlog/stdlib.py", line 119, in _proxy_to_logger
    **event_kw)
  File "/home/ethan/Jobs/Mozilla/tmp/structlog-bug/.venv/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 "/home/ethan/Jobs/Mozilla/tmp/structlog-bug/.venv/lib/python2.7/site-packages/structlog/_base.py", line 136, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
  File "/home/ethan/Jobs/Mozilla/tmp/structlog-bug/.venv/lib/python2.7/site-packages/structlog/stdlib.py", line 327, in filter_by_level
    if logger.isEnabledFor(_NAME_TO_LEVEL[name]):
AttributeError: 'PrintLogger' object has no attribute 'isEnabledFor'

This makes it difficult to log messages during startup, because logging isn't configured yet, and if we log messages before we configure, later log messages will just crash and burn with this exception.

Ref: https://github.com/hynek/structlog/pull/23

Apologies for opening another PR for same issue. I didn't want to pollute the original author's PR.

I addressed all of your comments that I agreed with and added a commit. I retained the original author's commit as well. Tox tests pass on my box.

I disagreed with one comment about adding pass through methods in stdlib BoundLogger (https://github.com/hynek/structlog/pull/23/files#diff-519ce9a9803f8404219d01de0afb0c1fR65). There are more than 5 such methods that are in stdlib logger. I was reading the code for the first time and instantly got what getattr was trying to do. I don't feel like it's magic. If you still insist on explicit pass through methods, I can add a commit. Please let me know.

Summary

Parse tracebacks into an object structure than can easily be converted, e.g., to JSON. The code is based on rich (I talked to @willmcgugan and he is okay with that) but simplified and stripped of every "pretty printing" functionality. It’s main goal is to produce structured tracebacks that can be parsed by log aggregators.

This is still work-in-progress. TODO:

• Documentation
• How to integrate it with structlog? I currently use an orjson processor that also calls the traceback parser (similar to what the ConsoleRenderer does with rich):

import sys

import orjson
import structlog
from structlog.processors import _json_fallback_handler as orjson_fallback_handler
from structlog.types import EventDict, WrappedLogger


def render_orjson(_logger: WrappedLogger, _name: str, event_dict: EventDict) -> str:
    """
    Modified version of :class:`structlog.processors.JSONRenderer` that works around
    the issues in https://github.com/hynek/structlog/issues/360
    """
    exc_info = event_dict.pop("exc_info", None)
    if exc_info:
        event_dict["exception"] = get_traceback_dicts(exc_info)

    return orjson.dumps(event_dict, default=orjson_fallback_handler).decode()


def fail():
    1 / 0


def main():
    processors = [
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(),
    ]
    if sys.stdout.isatty():
        processors.append(structlog.dev.ConsoleRenderer())
    else:
        processors.append(render_orjson)

    structlog.configure(
        processors=processors,
    )
    log = structlog.get_logger()
    log.info("ohai")


    try:
        fail()
    except Exception as e:
        log.exception("onoes", exc_info=e)


if __name__ == "__main__":
    main()

Output:

# python tb.py 2>&1 | jq
{
  "event": "ohai",
  "level": "info",
  "timestamp": 1648975014.737222
}
{
  "event": "onoes",
  "level": "error",
  "timestamp": 1648975014.7372942,
  "exception": [
    {
      "exc_type": "ZeroDivisionError",
      "exc_value": "division by zero",
      "syntax_error": null,
      "is_cause": false,
      "frames": [
        {
          "filename": "/Users/stefan/Projects/typed-settings/tb.py",
          "lineno": 280,
          "name": "main",
          "line": "",
          "locals": {
            "processors": "'[<function add_log_level at 0x109a1dfc0>, <structlog.processors.TimeStamper obje'+60",
            "log": "'<BoundLoggerLazyProxy(logger=None, wrapper_class=None, processors=None, context_'+55",
            "e": "ZeroDivisionError('division by zero')"
          }
        },
        {
          "filename": "/Users/stefan/Projects/typed-settings/tb.py",
          "lineno": 259,
          "name": "fail",
          "line": "",
          "locals": {}
        }
      ]
    }
  ]
}

Pull Request Check List

• [x] Added tests for changed code.
  • The CI fails with less than 100% coverage.
• [x] New APIs are added to typing_examples.py.
• [x] Updated documentation for changed code.
  • [x] New functions/classes have to be added to docs/api.rst by hand.
  • [x] Changed/added classes/methods/functions have appropriate versionadded, versionchanged, or deprecated directives. Find the appropriate next version in our __init__.py file.
• [x] Documentation in .rst and .md files is written using semantic newlines.
• [x] Changes (and possible deprecations) are documented in the changelog.
• [x] Consider granting push permissions to the PR branch, so maintainers can fix minor issues themselves without pestering you.

Similarly to #266, I find myself needing to access the thread-local context (I need to re-estabish some bound variables after a clean_threadlocal()).

I tried to use structlog.get_context() but it's not returning the threadlocal context. If this would be accepted, I might even come up with a PR.

Hi Hynek,

I would like to add stubs for structlog to https://github.com/python/typeshed, a repository used to store PEP 484 type signatures for the Python stdlib and popular third party libraries. As per PEP 484, permission is required from the library owner before merging type signatures into typeshed - https://www.python.org/dev/peps/pep-0484/#the-typeshed-repo

These stubs will be used by mypy and Pycharm. I'll start working on creating stubs after I get permission from you and do let me know if you have any suggestions.

Thanks

Summary

👋🏾 I'm extremely new to this project (as in just trying it out today 😅 ).

I came across this issue as I was playing around with it. Perhaps, I'm doing something wrong? If not, this is my attempt to fix it.

Before my changes:

>>> from structlog import get_logger
>>> logger = get_logger()
>>> logger.exception("boom! code: %i", 42)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: exception() takes 2 positional arguments but 3 were given

After:

>>> from structlog import get_logger
>>> logger = get_logger()
>>> logger.exception("boom! code: %i", 42)
2023-01-07 01:59:28 [error    ] boom! code: 42 
NoneType: None

If this looks like I'm on the right track I will complete the doc changes as mentioned in the checklist, but I wanted to get some feedback first if that is alright. Thanks!

Pull Request Check List

• [x] Added tests for changed code.
  • The CI fails with less than 100% coverage.
• [ ] New APIs are added to typing_examples.py.
• [ ] Updated documentation for changed code.
  • [ ] New functions/classes have to be added to docs/api.rst by hand.
  • [ ] Changed/added classes/methods/functions have appropriate versionadded, versionchanged, or deprecated directives. Find the appropriate next version in our __init__.py file.
• [ ] Documentation in .rst and .md files is written using semantic newlines.
• [ ] Changes (and possible deprecations) are documented in the changelog.
• [x] Consider granting push permissions to the PR branch, so maintainers can fix minor issues themselves without pestering you.

Summary

If the exc_info key was filled with a raw exception, and not a tuple, the ConsoleRenderer code would call sys.exc_info and overwrite it. This is different to how the other processors handle the exc_info key.

Closes #482

Pull Request Check List

• [ ] Added tests for changed code.
  • The CI fails with less than 100% coverage.
• [ ] New APIs are added to typing_examples.py.
• [ ] Updated documentation for changed code.
  • [ ] New functions/classes have to be added to docs/api.rst by hand.
  • [ ] Changed/added classes/methods/functions have appropriate versionadded, versionchanged, or deprecated directives. Find the appropriate next version in our __init__.py file.
• [ ] Documentation in .rst and .md files is written using semantic newlines.
• [ ] Changes (and possible deprecations) are documented in the changelog.
• [ ] Consider granting push permissions to the PR branch, so maintainers can fix minor issues themselves without pestering you.

First, thank you for this great package.

We are using structlog for creating canonical logs in a lambda function. The entrypoint of the lambda function calls another method which handles the event. This method never raises, but code within the other method might trap an exception and place it in the contextvar key exc_info .

In production, we log output as json and everything is fine. For local development, we are using the console renderer, but the exceptions are not handled properly unless the exc_key contains a tuple.

Here is a minimal reproduction:

import structlog
from structlog.contextvars import bind_contextvars

logger = structlog.stdlib.get_logger()

def process():
    bind_contextvars(event_id="123")
    # do some things, but don't propagate the exception
    try:
        print("Running...")

        raise ValueError("Boom")
    except Exception as exc:
        bind_contextvars(exc_info=exc)

    print("Finished...")

def run():
    try:
        process()
    finally:
        logger.info("canonical-log")

if __name__ == "__main__":
    run()

When running, this explodes while handling the log:

$ poetry run python3 main.py
Running...
Finished...
Traceback (most recent call last):
  File "/Users/aclemons/worksp/structlog-test/main.py", line 25, in <module>
    run()
  File "/Users/aclemons/worksp/structlog-test/main.py", line 22, in run
    logger.info("canonical-log")
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/structlog/_log_levels.py", line 157, in meth
    return self._proxy_to_logger(name, event, **kw)
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/structlog/_base.py", line 205, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/structlog/_base.py", line 162, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/structlog/dev.py", line 424, in __call__
    self._exception_formatter(sio, exc_info)
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/structlog/dev.py", line 187, in rich_traceback
    Traceback.from_exception(*exc_info, show_locals=True)
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/rich/traceback.py", line 292, in from_exception
    rich_traceback = cls.extract(
  File "/Users/aclemons/Library/Caches/pypoetry/virtualenvs/structlog-test-wfc9biWa-py3.9/lib/python3.9/site-packages/rich/traceback.py", line 348, in extract
    exc_type=safe_str(exc_type.__name__),
AttributeError: 'NoneType' object has no attribute '__name__'

If the exception is propagated it works without problem.

It looks like the problem is here:

https://github.com/hynek/structlog/blob/22.3.0/src/structlog/dev.py#L420-L424

Since exc_info is not a tuple, it calls sys.exc_info, but we are not currently handling an exception and this returns None values.

Would it be appropriate to replace that with the following code?

        if exc_info:
            self._exception_formatter(sio, _figure_out_exc_info(exc_info))

That is what ExceptionRenderer is using here. This then works for me.

$ poetry run python3 other.py
Running...
Finished...
2022-12-06 10:40:27 [info     ] canonical-log                  event_id=123
╭─────────────────────────────── Traceback (most recent call last) ────────────────────────────────╮
│ /Users/aclemons/worksp/structlog-test/other.py:25 in process                                     │
│                                                                                                  │
│   22 │   try:                                                                                    │
│   23 │   │   print("Running...")                                                                 │
│   24 │   │                                                                                       │
│ ❱ 25 │   │   raise ValueError("Boom")                                                            │
│   26 │   except Exception as exc:                                                                │
│   27 │   │   bind_contextvars(exc_info=exc)                                                      │
╰──────────────────────────────────────────────────────────────────────────────────────────────────╯
ValueError: Boom

Summary

Reworking a few things to allow make_filtering_bound_logger to provide FilteringBoundLogger's that inherit from BoundLogger instead of BoundLoggerBase which results in stdlib logger compatibility. Additionally adding a wrapper property for filters which was missing from BoundLogger.

This should close #469 and result in the docs matching what's being provided by make_filtering_bound_logger, so I believe no documentation will need to be updated.

Pull Request Check List

• [x] Added tests for changed code.
  • The CI fails with less than 100% coverage.
• [x] New APIs are added to typing_examples.py.
• [x] Updated documentation for changed code.
  • [x] New functions/classes have to be added to docs/api.rst by hand.
  • [x] Changed/added classes/methods/functions have appropriate versionadded, versionchanged, or deprecated directives. Find the appropriate next version in our __init__.py file.
• [x] Documentation in .rst and .md files is written using semantic newlines.
• [x] Changes (and possible deprecations) are documented in the changelog.
• [x] Consider granting push permissions to the PR branch, so maintainers can fix minor issues themselves without pestering you.

While trying to use structlog as a drop in for the stdlib logger usage in slack_bolt, I encountered a variety of errors stemming from missing wrapper implementations.

Error example:

AttributeError: 'BoundLoggerFilteringAtDebug' object has no attribute 'disabled'

The root cause appears to be make_filtering_bound_logger's usage of BoundLoggerBase instead of the fully implemented BoundLogger. BoundLogger itself is missing the filters wrapper, but that is trivial to fix. BoundLoggerBase is missing all of the wrapper logic and that appears intentional.

With an analog to BoundLogger implemented I am able to use structlog as a drop-in replacement for the standard logger.

I'll be tying in a pull request with a proposed solution.