Add ProcessorFormatter

[hynek]

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.

[codecov]

Codecov Report

Merging #105 into master will not change coverage.
The diff coverage is 100%.

@@          Coverage Diff          @@
##           master   #105   +/-   ##
=====================================
  Coverage     100%   100%           
=====================================
  Files          13     13           
  Lines         754    774   +20     
  Branches       94     96    +2     
=====================================
+ Hits          754    774   +20

Impacted Files	Coverage Δ
src/structlog/stdlib.py	100% <100%> (ø)	⬆️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update efae84e...4a12a2f. Read the comment docs.

[insolite]

@hynek Yes, that is exactly the thing I was thinking of.

The idea with foreign_pre_chain looks very interesting. But what if processor also will be something that is up to foreign_pre_chain? I mean that we can remove ProcessorFormatter.processor at all and use more generalized foreign_pre_chain set. Like this:

ProcessorFormatter:

class ProcessorFormatter(logging.Formatter):

    def __init__(self, processors=None, *args, **kwargs):
        fmt = kwargs.pop("fmt", "%(message)s")
        super(ProcessorFormatter, self).__init__(*args, fmt=fmt, **kwargs)
        self.processors = processors

    def format(self, record):
        """
        Extract ``structlog``'s `event_dict` from ``record.msg`` and format it.
        """
        if isinstance(record.msg, dict):
            meth_name = record._name
            # We need to copy because it's possible that the same record gets
            # processed by multiple logging formatters.
            ed = record.msg.copy()
        else:
            if self.processors is None:
                # Let logging format the message.
                return super(ProcessorFormatter, self).format(record)
            # Non-structlog allows to run through a chain to prepare it for the
            # final processor (e.g. adding timestamps and log levels).
            ed = {"event": record.getMessage()}
            meth_name = record.levelname.lower()
        for proc in self.processors:
            ed = proc(None, meth_name, ed)

        return ed

Config:

    logging.config.dictConfig({
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {
            'plain': {
                '()': structlog.stdlib.ProcessorFormatter,
                'processors': (structlog.dev.ConsoleRenderer(colors=False),),
            },
            'colored': {
                '()': structlog.stdlib.ProcessorFormatter,
                'processors': (structlog.dev.ConsoleRenderer(colors=True),),
            },
        },
        'handlers': {
            'default': {
                'level': 'DEBUG',
                'class': 'logging.StreamHandler',
                'formatter': 'colored',
            },
            'file': {
                'level': 'DEBUG',
                'class': 'logging.handlers.WatchedFileHandler',
                'filename': 'test.log',
                'formatter': 'plain',
            },
        },
        'loggers': {
            '': {
                'handlers': ['default', 'file'],
                'level': 'DEBUG',
                'propagate': True,
            },
        }
    })
    structlog.configure(
        processors=[
            structlog.stdlib.add_log_level,
            structlog.stdlib.PositionalArgumentsFormatter(),
            structlog.processors.TimeStamper(fmt='%Y-%m-%d %H:%M:%S'),
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        context_class=dict,
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
        cache_logger_on_first_use=True,
    )

I did some simple tests locally, but I could miss something. If it's ok, I can prepare a PR soon if you want.

[if-fi]

@hynek works like a charm! Thank you!
I have even started using this branch right away.

My use case is the following:
I want to dump the same logging messages into 2 files - one json formatted and one colorless dev formatted.

[hynek]

@insolite I think your approach doesn’t fix my problem (and the problem ten people complain each week :)) though: the point of foreign_pre_chain is specifically to mold non-structlog log entries into something the structlog processor understands or to complete meta data. It doesn’t just allow for your (and Iva’s) need for multiplexing but also gives you first-class stdlib → structlog integration.

Or am I missing something here? Just came back from a vacation, so my memory may be clouded. :)

[if-fi]

@hynek I have tried logging with the following configuration

        'plain_struct': {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(colors=False),
            "foreign_pre_chain": pre_chain,
            'format': '\n%(message)s [in %(pathname)s:%(lineno)d]',
        },

but for me the format config is not taken into account at all and no pathname and line number are printed in the log.

If I use structlog.dev.ConsoleRenderer() directly instead of combination with
structlog.stdlib.ProcessorFormatter.wrap_for_formatter, they are printed fine.

[if-fi]

You are not actually formatting the message anywhere in this method.
So if you have a logging configuration like 'format': u'\n%(message)s [in %(pathname)s:%(lineno)d]', you are not respecting that. And the end format is always the plain message only.

[if-fi]

@hynek I left you a comment in the code where I think the problem occurs.
To work around this problem in my local setup I have overridden the format method and now the formatting works fine for me

class ProcessorFormatterFix(ProcessorFormatter):
    def format(self, record):
        record.msg = super(ProcessorFormatterFix, self).format(record)
        return super(ProcessorFormatter, self).format(record)

[hynek]

Good catch! Do you think formatting should be unconditional like you do? Because I’d tend to only do that for the stdlib-case.

E.g. replace ed = {"event": record.getMessage()} by ed = {"event": super(ProcessorFormatter, self).format(record)} or something.

[hynek]

ping @if-fi (sorry, I’m not comfortable to make decisions w/o double checking with competent people here :))

[if-fi]

Hey @hynek, sorry for missing your previous comment.
I personally would recommend to do it unconditionally. I cannot think of a usecase where someone will add a format configuration to their logging system and they would not want it to be respected and used.

In my current usecase, I do the additional formatting for the structlog messages themselves. I could not find a processor that adds lineno and pathname through structlog, so I do it via formatting.
But I'm sure other people will want to play with different formattings as well.

Moreover, the other processors respect the external formatting configuration, so it will be a great inconsistency if ProcessorFormatter respects it only for the stdlib.

[hynek]

Hey @if-fi, how about now?

Happy Easter everyone 🐥🙈. Thank you for indulging me, we can do it. :)

[if-fi]

Happy easter :)
It looks good in code now @hynek. I will test it in real life in my project today or tomorrow and I'll ping you if I find any problems

[hynek]

Thank you so much! Looking forward to your feedback!

[if-fi]

@hynek now the formatting works fine :)
But when I log to console locally, something strange happens. My log messages are messing up with the nginx log entries in a way I have never seen before

(see the bottom, how the red nginex log entry appears in the middle of the structlog entry)

Could this be caused by structlog?

[hynek]

Uhhhh the actual output is done by logging, no? I can’t think of ways how it could be structlog’s fault if that’s true?

[if-fi]

I can't think of a way how this can be caused by structlog as well...
Let's leave it like that. If find some base for complaining, I will open a separate issue here.

[hynek]

FYI, 17.1 is on PyPI. Have fun with it and thanks once more everyone!

[if-fi]

Thank you, @hynek!