Logging variable data with new format string

Posted on

Question :

Logging variable data with new format string

I use logging facility for python 2.7.3. Documentation for this Python version say:

the logging package pre-dates newer formatting options such as str.format() and string.Template. These newer formatting options are supported…

I like ‘new’ format with curly braces. So i’m trying to do something like:

 log = logging.getLogger("some.logger")
 log.debug("format this message {0}", 1)

And get error:

TypeError: not all arguments converted during string formatting

What I miss here?

P.S. I don’t want to use

log.debug("format this message {0}".format(1))

because in this case the message is always being formatted regardless of logger level.

Answer #1:

EDIT: take a look at the StyleAdapter approach in @Dunes’ answer unlike this answer; it allows to use alternative formatting styles without the boilerplate while calling logger’s methods (debug(), info(), error(), etc).


From the docs — Use of alternative formatting styles:

Logging calls (logger.debug(), logger.info() etc.) only take
positional parameters for the actual logging message itself, with
keyword parameters used only for determining options for how to handle
the actual logging call (e.g. the exc_info keyword parameter to
indicate that traceback information should be logged, or the extra
keyword parameter to indicate additional contextual information to be
added to the log). So you cannot directly make logging calls using
str.format() or string.Template syntax, because internally the logging
package uses %-formatting to merge the format string and the variable
arguments. There would no changing this while preserving backward
compatibility, since all logging calls which are out there in existing
code will be using %-format strings.

And:

There is, however, a way that you can use {}- and $- formatting to
construct your individual log messages. Recall that for a message you
can use an arbitrary object as a message format string, and that the
logging package will call str() on that object to get the actual
format string.

Copy-paste this to wherever module:

class BraceMessage(object):
    def __init__(self, fmt, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

Then:

from wherever import BraceMessage as __

log.debug(__('Message with {0} {name}', 2, name='placeholders'))

Note: actual formatting is delayed until it is necessary e.g., if DEBUG messages are not logged then the formatting is not performed at all.

Answered By: jfs

Answer #2:

Here is another option that does not have the keyword problems mentioned in Dunes’ answer. It can only handle positional ({0}) arguments and not keyword ({foo}) arguments. It also does not require two calls to format (using the underscore). It does have the ick-factor of subclassing str:

class BraceString(str):
    def __mod__(self, other):
        return self.format(*other)
    def __str__(self):
        return self


class StyleAdapter(logging.LoggerAdapter):

    def __init__(self, logger, extra=None):
        super(StyleAdapter, self).__init__(logger, extra)

    def process(self, msg, kwargs):
        if kwargs.pop('style', "%") == "{":  # optional
            msg = BraceString(msg)
        return msg, kwargs

You use it like this:

logger = StyleAdapter(logging.getLogger(__name__))
logger.info("knights:{0}", "ni", style="{")
logger.info("knights:{}", "shrubbery", style="{")

Of course, you can remove the check noted with # optional to force all messages through the adapter to use new-style formatting.


Note for anyone reading this answer years later: Starting with Python 3.2, you can use the style parameter with Formatter objects:

Logging (as of 3.2) provides improved support for these two additional formatting styles. The
Formatter class been enhanced to take an additional, optional keyword parameter named style. This
defaults to '%', but other possible values are '{' and '$', which correspond to the other two
formatting styles. Backwards compatibility is maintained by default (as you would expect), but by
explicitly specifying a style parameter, you get the ability to specify format strings which work
with str.format() or
string.Template.

The docs provide the example
logging.Formatter('{asctime} {name} {levelname:8s} {message}', style='{')

Note that in this case you still can’t call the logger with the new format. I.e., the following still won’t work:

logger.info("knights:{say}", say="ni")  # Doesn't work!
logger.info("knights:{0}", "ni")  # Doesn't work either
Answered By: Felipe

Answer #3:

This was my solution to the problem when I found logging only uses printf style formatting. It allows logging calls to remain the same — no special syntax such as log.info(__("val is {}", "x")). The change required to code is to wrap the logger in a StyleAdapter.

from inspect import getargspec

class BraceMessage(object):
    def __init__(self, fmt, args, kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return str(self.fmt).format(*self.args, **self.kwargs)

class StyleAdapter(logging.LoggerAdapter):
    def __init__(self, logger):
        self.logger = logger

    def log(self, level, msg, *args, **kwargs):
        if self.isEnabledFor(level):
            msg, log_kwargs = self.process(msg, kwargs)
            self.logger._log(level, BraceMessage(msg, args, kwargs), (), 
                    **log_kwargs)

    def process(self, msg, kwargs):
        return msg, {key: kwargs[key] 
                for key in getargspec(self.logger._log).args[1:] if key in kwargs}

Usage is:

log = StyleAdapter(logging.getLogger(__name__))
log.info("a log message using {type} substitution", type="brace")

It’s worth noting that this implementation has problems if key words used for brace substitution include level, msg, args, exc_info, extra or stack_info. These are argument names used by the log method of Logger. If you need to one of these names then modify process to exclude these names or just remove log_kwargs from the _log call. On a further note, this implementation also silently ignores misspelled keywords meant for the Logger (eg. ectra).

Answered By: Dunes

Answer #4:

The easier solution would be to use the excellent logbook module

import logbook
import sys

logbook.StreamHandler(sys.stdout).push_application()
logbook.debug('Format this message {k}', k=1)

Or the more complete:

>>> import logbook
>>> import sys
>>> logbook.StreamHandler(sys.stdout).push_application()
>>> log = logbook.Logger('MyLog')
>>> log.debug('Format this message {k}', k=1)
[2017-05-06 21:46:52.578329] DEBUG: MyLog: Format this message 1
Answered By: Thomas Orozco

Answer #5:

As other answers mention, the brace-style formatting introduced in Python 3.2 is only used on the format string, not the actual log messages.

To enable brace-style formatting on the actual log message, we can monkey-patch a bit of the logger code.

The following patches the logging module to create a get_logger function that will return a logger that uses the new-style formatting for every log record that it handles.

import functools
import logging
import types

def _get_message(record):
    """Replacement for logging.LogRecord.getMessage
    that uses the new-style string formatting for
    its messages"""
    msg = str(record.msg)
    args = record.args
    if args:
        if not isinstance(args, tuple):
            args = (args,)
        msg = msg.format(*args)
    return msg

def _handle_wrap(fcn):
    """Wrap the handle function to replace the passed in
    record's getMessage function before calling handle"""
    @functools.wraps(fcn)
    def handle(record):
        record.getMessage = types.MethodType(_get_message, record)
        return fcn(record)
    return handle

def get_logger(name=None):
    """Get a logger instance that uses new-style string formatting"""
    log = logging.getLogger(name)
    if not hasattr(log, "_newstyle"):
        log.handle = _handle_wrap(log.handle)
    log._newstyle = True
    return log

Usage:

>>> log = get_logger()
>>> log.warning("{!r}", log)
<logging.RootLogger object at 0x4985a4d3987b>

Notes:

  • Fully compatible with normal logging methods (just replace logging.getLogger with get_logger)
  • Will only affect specific loggers created by the get_logger function (doesn’t break 3rd party packages).
  • If the logger is accessed again from a normal logging.getLogger() call, the new-style formatting will still apply.
  • kwargs are not supported (makes it impossible to conflict with the built-in exc_info, stack_info, stacklevel and extra).
  • Performance hit should be minimal (rewriting a single function pointer for each log message).
  • The formatting of the message is delayed until it is output (or not at all if the log message is filtered).
  • Args are stored on logging.LogRecord objects as usual (useful in some cases with custom log handlers).
  • From looking at the logging module source code it seems like it should work all the way back to Python 2.6 when str.format was introduced (but I’ve only tested it in 3.5 and up)
Answered By: pR0Ps

Answer #6:

Try logging.setLogRecordFactory in Python 3.2+:

import collections
import logging


class _LogRecord(logging.LogRecord):

    def getMessage(self):
        msg = str(self.msg)
        if self.args:
            if isinstance(self.args, collections.Mapping):
                msg = msg.format(**self.args)
            else:
                msg = msg.format(*self.args)
        return msg


logging.setLogRecordFactory(_LogRecord)
Answered By: nexcvon

Answer #7:

I created a custom Formatter, called ColorFormatter that handles the problem like this:

class ColorFormatter(logging.Formatter):

    def format(self, record):
        # previous stuff, copy from logging.py…

        try:  # Allow {} style
            message = record.getMessage()  # printf
        except TypeError:
            message = record.msg.format(*record.args)

        # later stuff…

This keeps it compatible with various libraries.
The drawback is that it is probably not performant due to potentially attempting format of the string twice.

Answered By: Gringo Suave

Answer #8:

Similar solution to pR0Ps’ , wrapping getMessage in LogRecord by wrapping makeRecord (instead of handle in their answer) in instances of Logger that should be new-formatting-enabled:

def getLogger(name):
    log = logging.getLogger(name)
    def Logger_makeRecordWrapper(name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None):
        self = log
        record = logging.Logger.makeRecord(self, name, level, fn, lno, msg, args, exc_info, func, sinfo)
        def LogRecord_getMessageNewStyleFormatting():
            self = record
            msg = str(self.msg)
            if self.args:
                msg = msg.format(*self.args)
            return msg
        record.getMessage = LogRecord_getMessageNewStyleFormatting
        return record
    log.makeRecord = Logger_makeRecordWrapper
    return log

I tested this with Python 3.5.3.

Answered By: Dragorn421

Leave a Reply

Your email address will not be published. Required fields are marked *