How to log using style='{'

user_5696589 0
Viewed 124

I am using Python 3.8.10. I am trying to use the logging style '{'. From the documentation under formatters

It states the following

If the style is ‘%’, the message format string uses %()s styled string substitution; the possible keys are documented in LogRecord attributes. If the style is ‘{‘, the message format string is assumed to be compatible with str.format() (using keyword arguments), while if the style is ‘$’ then the message format string should conform to what is expected by string.Template.substitute().

I am having a problem getting style='{' to work correctly. Specifically passing the keyword arguments it needs per the docs.

import logging

logger = logging.getLogger(__name__) 

formatter = logging.Formatter('{asctime} - {name} - {levelname} - {message}',style='{')

scrnhandler = logging.StreamHandler()
scrnhandler.setLevel(logging.INFO)
scrnhandler.setFormatter(formatter)

logger.addHandler(scrnhandler)
logger.level = logging.INFO

logger.info("plain message as base case")    #<-- Works, no args passed

mystr = "Input args: {0:f}".format(10)       #<-- This is supposed to be str.format this is to be followed

logger.info("Input args: {0:f}", 10)         #<-- Does not work, I assume it wants a 'named argument'
logger.info("Input args: {args[0]:f}", 10)   #<-- Does not work, 
                                         # I know the data goes into the LogRecord args attribute so tried that
                                         
logger.info("Input args: {a:f}", a=10)       #<-- Does not work, is looking for more args to parse

I have not been able to find an example that shows how to use logging following this style, can someone help me figure out the nuance that am I missing to use this style of logging?

logging python
1 Answers

I've been there a while ago, and also was confused. And at least a couple more developers felt the same, as there's bpo14031.

Summary

Summary is provided in Python documentation in Use of alternative formatting styles (from the BPO).

When logging was added to the Python standard library, the only way of formatting messages with variable content was to use the %-formatting method.

[...]

Note that the formatting of logging messages for final output to logs is completely independent of how an individual logging message is constructed.

[...]

[...] 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 be no changing this while preserving backward compatibility, since all logging calls which are out there in existing code will be using %-format strings.

Translating this into Python would mean this.

In [1]: import logging

In [2]: # this is roughly how result of "logging.info('foo %s', 'bar')" looks
   ...: dummy = logging.makeLogRecord({'msg': 'foo %s', 'args': ('bar',)})

In [3]: # logger.Formatter roughly works as follows
   ...: dummy.message = dummy.getMessage()         # ①
   ...: '%(message)s' % dummy.__dict__             # ②
Out[3]: 'foo bar'

In [4]: '{message}'.format(**dummy.__dict__)       # ③
Out[4]: 'foo bar'

② and ③ are configurable (there's also string.Template option), ① is not and all it is is:

def getMessage(self):
    """
    Return the message for this LogRecord.
    Return the message for this LogRecord after merging any user-supplied
    arguments with the message.
    """
    msg = str(self.msg)
    if self.args:
        msg = msg % self.args
    return msg

And sure, since Python 3.2 log record factory is configurable via logging.setLogRecordFactory as described in Customizing LogRecord. But sub-classing it, overriding getMessage and replacing msg = msg % self.args with msg = msg.format(self.args)* will break all existing code using logging and passing arguments (likely in subtle ways depending on the logging level).

Solution

I was thinking how to override getMessage to make is backward-compatible with %-style, support {-style and also not become too slow. Here's what I've come to.

import collections.abc
import logging


class StrFormatLogRecord(logging.LogRecord):
    """
    Drop-in replacement for ``LogRecord`` that supports ``str.format``.
    """

    def getMessage(self):
        msg = str(self.msg)
        if self.args:
            try:
                msg = msg % ()
            except TypeError:
                # Either or the two is expected indicating there's
                # a placeholder to interpolate:
                #
                # - not all arguments converted during string formatting
                # - format requires a mapping" expected
                #
                # If would've been easier if Python printf-style behaved
                # consistently for "'' % (1,)" and "'' % {'foo': 1}". But
                # it raises TypeError only for the former case.
                msg = msg % self.args
            else:
                # There's special case of first mapping argument. See
                # duner init of logging.LogRecord.
                if isinstance(self.args, collections.abc.Mapping):
                    msg = msg.format(**self.args)
                else:
                    msg = msg.format(*self.args)
                
        return msg

And it can be used like:

def main():
    args = {'arg1': 10, 'arg2': 20}
    logging.info('Input args: %.2f %.2f', *args.values())
    logging.info('Input args: %d %d', *args.values())
    logging.info('Input args: %s %s', *args.values())
    logging.info('Input args: %(arg1).2f %(arg2).2f', args)
    logging.info('Input args: %(arg1)d %(arg2)d', args)
    logging.info('Input args: %(arg1)s %(arg2)s', args)
    logging.info('Input args: {0:.2f} {1:.2f}', *args.values())
    logging.info('Input args: {0:d} {1:d}', *args.values())
    logging.info('Input args: {0} {1}', *args.values())
    logging.info('Input args: {arg1:.2f} {arg2:.2f}', args)
    logging.info('Input args: {arg1:d} {arg2:d}', args)
    logging.info('Input args: {arg1} {arg2}', args)


if __name__ == '__main__':
    logging.basicConfig(
        level=logging.INFO,
        format='{asctime} {message}',
        style='{',
    )
    logging.setLogRecordFactory(StrFormatLogRecord)
    
    main()

In all 4 cases it produces correctly formatted output. But it's not unlikely that there's still a couple of edge-cases where it breaks or formats incorrectly (and that's besides the case when a str.format template contains a printf-style placeholder, but it's up to you whether it's relevant).

... Input args: 10.00 20.00
... Input args: 10 20
... Input args: 10 20
user_20720350
Related