0

I'm trying to use str.format style templating in my logging. Can't seem to get it working properly.

>>> import logging
>>> logging.basicConfig(filename='/tmp/example', format='{asctime} - {levelname} - {message}', style='{', level=logging.INFO)
>>> logger = logging.getLogger(__name__)
>>> logger.warning('blah')
>>> logger.warning('{foo:03d}', {'foo': 42})

Actual output:

2017-02-23 16:11:45,695 - WARNING - blah
2017-02-23 16:12:11,432 - WARNING - {foo:03d}

Expected output:

2017-02-23 16:11:45,695 - WARNING - blah
2017-02-23 16:12:11,432 - WARNING - 042

What am I missing in this setup?

I'm not interested to see workarounds that format the string before it's logged, or Python 2 solutions which use old %-style templating.

Community
  • 1
  • 1
wim
  • 338,267
  • 99
  • 616
  • 750

2 Answers2

4

Apparently the style argument only applies to information about messages (such as a timestamp, severity, etc.) and not to actual messages.

From the docstring of logger.warning:

warning(msg, *args, **kwargs) method of logging.Logger instance
    Log 'msg % args' with severity 'WARNING'.

It seems that the msg is always formatted using old-style formatting, so the style argument of the logger is not even considered.

The logging HOWTO contains a bit more information:

... 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.

vaultah
  • 44,105
  • 12
  • 114
  • 143
-1

"I'm not interested to see workarounds that format the string before it's logged" Why not? The old style formats it before it's logged also... You can put the line to do the formatting inside the logger.warning call and it changes nothing functionally. If {foo:42} is just one member of a much larger dictionary you can do something like this:

for key,val in warningsDictionary.iteritems():
    logger.warning('{'+key+':'+format(val,'03')+'}')

Whether or not this is sufficient is dependent on what you actually are trying to do.

amoose136
  • 178
  • 1
  • 8
  • If we format the string before calling logger then log aggregation stuff doesn't work properly – wim Feb 23 '17 at 23:06
  • Could you be more specific? How does it not work properly? – amoose136 Feb 24 '17 at 00:07
  • 1
    Consider a message such as `logger.warning('problem with thing %(thing_id)03d', {'thing_id': 42})`. This will produce a log message like `problem with thing 042` in the output. However, log aggregation services such as `sentry` will group together `problem with thing 001`, `problem with thing 042`, `problem with thing 069` as different manifestations of the same warning. If you template the log record yourself, rather than letting the logger handle that, you lose all that functionality and you can get millions of distinct alerts (which should have just been 1 alert, with millions of hits). – wim Apr 24 '17 at 22:31