Skip to content

bpo-34844: logging.Formatter enhancement - Ensure styles and fmt matches in logging.Formatter #9703

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 21 commits into from
Oct 15, 2018
Merged

bpo-34844: logging.Formatter enhancement - Ensure styles and fmt matches in logging.Formatter #9703

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
21 commits
Select commit Hold shift + click to select a range
66bbddf
bpo-34844
BNMetrics Oct 4, 2018
0eaaf25
added news entry
BNMetrics Oct 4, 2018
f4f6a60
suggested changed before regex fix
BNMetrics Oct 5, 2018
d51e186
regex changes
BNMetrics Oct 6, 2018
cc2cfbd
commit
BNMetrics Oct 6, 2018
7c24e46
rewrote regex
BNMetrics Oct 6, 2018
abd868d
changes as requested
BNMetrics Oct 7, 2018
c1359bb
changes as requested
BNMetrics Oct 7, 2018
921ba33
added doc and docstring, added some of the original tests back for $ …
BNMetrics Oct 8, 2018
8484f29
changed validate method for StrFormatStyle
BNMetrics Oct 9, 2018
4c35216
changed on StrFormatStyle class
BNMetrics Oct 10, 2018
6eee298
commit
BNMetrics Oct 12, 2018
aab0c46
removed redundant debugging print
BNMetrics Oct 13, 2018
59879e9
added options to logging.config.dictConfig to allow passing in valida…
BNMetrics Oct 13, 2018
43c0b34
added in documentation for the validate key in logging.config.dictConfig
BNMetrics Oct 13, 2018
908c3ec
removing blank space
BNMetrics Oct 14, 2018
d73ab3a
rewrote logging.config.DictConfigurator.configure_formatter logic, si…
BNMetrics Oct 14, 2018
ff05742
document typo change on logging.rst
BNMetrics Oct 14, 2018
2664f85
reformatted logging.config.rst
BNMetrics Oct 14, 2018
74ca6a2
simplified the logic in logging.config.DictConfig.configure_formatter
BNMetrics Oct 15, 2018
de1243f
fixed document due to failure
BNMetrics Oct 15, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 41 additions & 5 deletions Lib/logging/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,10 +23,13 @@
To use, simply 'import logging' and log away!
"""

import sys, os, time, io, traceback, warnings, weakref, collections.abc
import sys, os, time, io, re, traceback, warnings, weakref, collections.abc

from string import Template

from contextlib import contextmanager
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is no longer needed - please remove.



__all__ = ['BASIC_FORMAT', 'BufferingFormatter', 'CRITICAL', 'DEBUG', 'ERROR',
'FATAL', 'FileHandler', 'Filter', 'Formatter', 'Handler', 'INFO',
'LogRecord', 'Logger', 'LoggerAdapter', 'NOTSET', 'NullHandler',
Expand Down Expand Up @@ -413,10 +416,10 @@ def makeLogRecord(dict):
rv.__dict__.update(dict)
return rv


#---------------------------------------------------------------------------
# Formatter classes and functions
#---------------------------------------------------------------------------

class PercentStyle(object):

default_format = '%(message)s'
Expand All @@ -426,19 +429,44 @@ class PercentStyle(object):
def __init__(self, fmt):
self._fmt = fmt or self.default_format

@contextmanager
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't understand the thinking behind this. Why do we need a context manager for this? Please explain, See other comments further below.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I used a context manager to avoid duplication, however I like your solution better. I'm going to make the change :)

def _verifyFields(self):
"""
Verify if fields passed into XXXStyle.
"""
try:
yield
except KeyError as e:
raise ValueError("Invalid formatting field %s" % e)

def usesTime(self):
return self._fmt.find(self.asctime_search) >= 0

def validate(self):
self._validateFormat(r'(\%\([^%()]+\)[\s\d-]*[\w]+)')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How did you arrive at this pattern? It doesn't seem to match the specification given here. It might be OK to match just the %(name)s part of the pattern, or any valid pattern, but not a halfway house. For example, your pattern matches %(name)Z and %(name)_, which are not valid for a format field specifier.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, this does seem to match the example you have given. let me try and redo this.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I have gotten quite a few things wrong in this pattern. I thought something like this would be valid%(asctime)- 15s, but looking at the specifications, I definitely got it wrong


def _validateFormat(self, expression):
matches = re.search(expression, self._fmt)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

matches could mean it matches or it could mean all the matches. Suggest renaming to matched as it is used in a Boolean sense.

if matches is None:
raise ValueError('Invalid format %(fmt)s for %(style)s style'
% {"fmt": self._fmt, "style": self.default_format[0]})
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You really don't need to use named values in the format string in this context. I gave a specific example in the earlier comment beginning "This would only be needed in PercentStyle:" - did you miss it? Also, you're not using a compiled pattern, as suggested.


def format(self, record):
return self._fmt % record.__dict__
with self._verifyFields():
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Before this PR, each of the format() methods is a one-liner which basically does return ... <result of formatting operation>. If you added a context manager to avoid duplicating the exception handling code [which it would be good to do], then it would be simpler to do as follows:

BEFORE:

in each XXXStyle class:

    def format(self, record):
        return ... <result of formatting operation>

AFTER:

In each XXXStyle class:

rename `def format(self, record)`  to `def _format(self, record)`

and in PercentStyle only (the base class for the others), define:

    def format(self, record):
        try:
            return self._format(self, record)
        except KeyError as e:
            raise ValueError('Formatting field not found in record: %s' % e)

With this approach, you avoid the duplication, without the need for a context manager, importing `contextlib` etc.

return self._fmt % record.__dict__


class StrFormatStyle(PercentStyle):
default_format = '{message}'
asctime_format = '{asctime}'
asctime_search = '{asctime'

def format(self, record):
return self._fmt.format(**record.__dict__)
with self._verifyFields():
return self._fmt.format(**record.__dict__)

def validate(self):
self._validateFormat(r'(\{[^{}]+\})')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How did you arrive at this pattern? It matches {name-thing}, which is not a great name for a key even though str.format() allows it if passing via a generic dictionary.

Copy link
Contributor Author

@BNMetrics BNMetrics Oct 5, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems reasonable, I will exclude some special characters in the keys



class StringTemplateStyle(PercentStyle):
Expand All @@ -455,7 +483,13 @@ def usesTime(self):
return fmt.find('$asctime') >= 0 or fmt.find(self.asctime_format) >= 0

def format(self, record):
return self._tpl.substitute(**record.__dict__)
with self._verifyFields():
return self._tpl.substitute(**record.__dict__)

def validate(self):
with self._verifyFields():
self._validateFormat(r'(\$\{[^${}]+\})')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How did you arrive at this pattern? It matches ${funcName} but fails to match $funcName which is valid for a $-formatting operation.



BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"

Expand Down Expand Up @@ -530,6 +564,8 @@ def __init__(self, fmt=None, datefmt=None, style='%'):
raise ValueError('Style must be one of: %s' % ','.join(
_STYLES.keys()))
self._style = _STYLES[style][0](fmt)
self._style.validate()

self._fmt = self._style._fmt
self.datefmt = datefmt

Expand Down
47 changes: 29 additions & 18 deletions Lib/test/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3163,7 +3163,13 @@ def verify_reverse(stuff):
], pat=r"^[\w.]+ -> (\w+): (\d+)$")

def test_out_of_order(self):
self.apply_config(self.out_of_order)
self.assertRaises(ValueError, self.apply_config, self.out_of_order)

def test_out_of_order_with_dollar_style(self):
config = self.out_of_order.copy()
config['formatters']['mySimpleFormatter']['format'] = "${asctime} (${name}) ${levelname}: ${message}"

self.apply_config(config)
handler = logging.getLogger('mymodule').handlers[0]
self.assertIsInstance(handler.target, logging.Handler)
self.assertIsInstance(handler.formatter._style,
Expand Down Expand Up @@ -3491,50 +3497,55 @@ def test_percent(self):
f = logging.Formatter('${%(message)s}')
self.assertEqual(f.format(r), '${Message with 2 placeholders}')
f = logging.Formatter('%(random)s')
self.assertRaises(KeyError, f.format, r)
self.assertRaises(ValueError, f.format, r)
self.assertFalse(f.usesTime())
f = logging.Formatter('%(asctime)s')
self.assertTrue(f.usesTime())
f = logging.Formatter('%(asctime)-15s')
self.assertTrue(f.usesTime())
f = logging.Formatter('asctime')
self.assertFalse(f.usesTime())
f = logging.Formatter('%(asctime) - 15s')
self.assertTrue(f.usesTime())
# Testing ValueError raised from mismatching format
self.assertRaises(ValueError, logging.Formatter, '{asctime}')
self.assertRaises(ValueError, logging.Formatter, '${message}')

def test_braces(self):
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would add an extra test test_format_validation that ensures that all valid kinds of format strings (for all styles) pass validation (paying attention to the detailed specs for format specifiers for each style), as well as checking that invalid formats fail with ValueError.

# Test {}-formatting
r = self.get_record()
f = logging.Formatter('$%{message}%$', style='{')
self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
f = logging.Formatter('{random}', style='{')
self.assertRaises(KeyError, f.format, r)
self.assertRaises(ValueError, f.format, r)
f = logging.Formatter("{message}", style='{')
self.assertFalse(f.usesTime())
f = logging.Formatter('{asctime}', style='{')
self.assertTrue(f.usesTime())
f = logging.Formatter('{asctime!s:15}', style='{')
self.assertTrue(f.usesTime())
f = logging.Formatter('{asctime:15}', style='{')
self.assertTrue(f.usesTime())
f = logging.Formatter('asctime', style='{')
self.assertFalse(f.usesTime())
# Testing ValueError raised from mismatching format
self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='{')

def test_dollars(self):
# Test $-formatting
r = self.get_record()
f = logging.Formatter('$message', style='$')
f = logging.Formatter('${message}', style='$')
self.assertEqual(f.format(r), 'Message with 2 placeholders')
f = logging.Formatter('$$%${message}%$$', style='$')
self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
f = logging.Formatter('${random}', style='$')
self.assertRaises(KeyError, f.format, r)
self.assertRaises(ValueError, f.format, r)
self.assertFalse(f.usesTime())
f = logging.Formatter('${asctime}', style='$')
self.assertTrue(f.usesTime())
f = logging.Formatter('${asctime', style='$')
f = logging.Formatter('${message}', style='$')
self.assertFalse(f.usesTime())
f = logging.Formatter('$asctime', style='$')
f = logging.Formatter('${asctime}--', style='$')
self.assertTrue(f.usesTime())
f = logging.Formatter('asctime', style='$')
self.assertFalse(f.usesTime())
# Testing ValueError raised from mismatching format
self.assertRaises(ValueError, logging.Formatter, '{asctime}', style='$')
self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='$')

def test_invalid_style(self):
self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
Expand Down Expand Up @@ -4000,10 +4011,10 @@ def test_stream(self):
self.assertEqual(handler.stream, stream)

def test_format(self):
logging.basicConfig(format='foo')
logging.basicConfig(format='%(asctime)s - %(message)s')

formatter = logging.root.handlers[0].formatter
self.assertEqual(formatter._style._fmt, 'foo')
self.assertEqual(formatter._style._fmt, '%(asctime)s - %(message)s')

def test_datefmt(self):
logging.basicConfig(datefmt='bar')
Expand Down Expand Up @@ -4032,11 +4043,11 @@ def test_incompatible(self):
handlers = [logging.StreamHandler()]
stream = sys.stderr
assertRaises(ValueError, logging.basicConfig, filename='test.log',
stream=stream)
stream=stream)
assertRaises(ValueError, logging.basicConfig, filename='test.log',
handlers=handlers)
handlers=handlers)
assertRaises(ValueError, logging.basicConfig, stream=stream,
handlers=handlers)
handlers=handlers)
# Issue 23207: test for invalid kwargs
assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO)
# Should pop both filename and filemode even if filename is None
Expand Down
6 changes: 6 additions & 0 deletions Misc/NEWS.d/next/Library/2018-10-04-20-44-45.bpo-34844.Hnuxav.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
logging.Formatter enhancement - Ensure styles and fmt matches in
logging.Formatter - Added validate method in each format style class:
StrFormatStyle, PercentStyle, StringTemplateStyle. - This method is called
in the constructor of logging.Formatter class - Also re-raise the KeyError
in the format method of each style class, so it would a bit clear that it's
an error with the invalid format fields.