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
vsajip 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 6 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
32 changes: 27 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

@vsajip vsajip Oct 7, 2018

Copy link
Copy Markdown
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,38 +416,54 @@ def makeLogRecord(dict):
rv.__dict__.update(dict)
return rv


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

class PercentStyle(object):

default_format = '%(message)s'
asctime_format = '%(asctime)s'
asctime_search = '%(asctime)'
validation_pattern = r'(\%\([^%()]+\)[#|0|\-|\s|+]?[\d]*[d|i|o|u|x|X|e|E|f|E|g|G|C|r|s|a|%]{1})'

@vsajip vsajip Oct 7, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

This still has some problems:

  • It is still not correct with respect to the spec - for example it doesn't handle the use of literal * to specify width and precision.
  • It's needlessly verbose - [d|i|o|u|x|X|e|E|f|E|g|G|C|r|s|a|%]{1} could be replaced with just [diouxefgcrsa] if compiled with re.I- excluding the % character, as that wouldn't make sense as part of a %(name) format specifier, and the {1} is redundant.
  • The bit between the parentheses - why not just use \w+?
  • When specifying character alternatives, you don't need a | - [#0+ -] would be preferable to [#|0|\-|\s|+], leaving the - at the end to avoid ambiguity, as otherwise - inside [...] has special meaning.
  • You didn't take up my point about using a compiled pattern. Did you not understand what I meant by that, or did you just forget it?

I suggest you just use re.compile(r'%\(\w+\)[#0+ -]?(\*|\d+)?(\.(\*|\d+))?[diouxefgcrsa]', re.I) as the validation_pattern.


def __init__(self, fmt):
self._fmt = fmt or self.default_format

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

def format(self, record):
def validate(self):
Comment thread
vsajip marked this conversation as resolved.
Resolved
if not re.search(self.validation_pattern, self._fmt):
raise ValueError('Invalid format %(fmt)s for %(style)s style'
% {"fmt": self._fmt, "style": self.default_format[0]})

@vsajip vsajip Oct 7, 2018

Copy link
Copy Markdown
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__

def format(self, record):
try:
return self._format(record)
except KeyError as e:
raise ValueError("Invalid formatting field %s" % e)

@vsajip vsajip Oct 7, 2018 •
edited
Loading

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I suggested earlier raise ValueError('Formatting field not found in record: %s' % e), as I thought that more informative. Do you not agree? "Invalid formatting field" suggests it might be improperly formatted, but the real problem is that it is not present in the record, and not how it's formatted (which your wording might be misinterpreted to mean).



class StrFormatStyle(PercentStyle):
default_format = '{message}'
asctime_format = '{asctime}'
asctime_search = '{asctime'
validation_pattern = r'(\{[^{!:}-]+(![r|s|a]{1})?(:[.]*[<|>|=]?[+|-|\s]?[\d]' \

@vsajip vsajip Oct 7, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

See my earlier comments about using tidy, correct and minimalist regex patterns and using a compiled pattern. Those comments also apply here.

r'*[b|c|d|e|E|f|F|g|G|n|o|s|x|X|%]{0,1})?\})'

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


class StringTemplateStyle(PercentStyle):
default_format = '${message}'
asctime_format = '${asctime}'
asctime_search = '${asctime}'
validation_pattern = r'(\$\{?[\w]+\}?)'

@vsajip vsajip Oct 7, 2018

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

See my earlier comments about using tidy, correct and minimalist regex patterns and using a compiled pattern. Those comments also apply here. For example, your pattern here allows the invalid values $foo} and ${foo.


def __init__(self, fmt):
self._fmt = fmt or self.default_format
Expand All @@ -454,9 +473,10 @@ def usesTime(self):
fmt = self._fmt
return fmt.find('$asctime') >= 0 or fmt.find(self.asctime_format) >= 0

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


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

_STYLES = {
Expand Down Expand Up @@ -530,6 +550,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()
Comment thread
vsajip marked this conversation as resolved.
Resolved

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

Expand Down
71 changes: 53 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,79 @@ 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())

def test_braces(self):

@vsajip vsajip Oct 5, 2018

Copy link
Copy Markdown
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())

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())

def test_format_validate(self):
f = logging.Formatter("%(asctime)-15s - %(message) 5s - %(process)03d - %(module)")
self.assertEqual(f._fmt, "%(asctime)-15s - %(message) 5s - %(process)03d - %(module)")
f = logging.Formatter("$%{message}%$ - {asctime!a:15} - {customfield['key']} - {process:.2f} - {custom.f:.4f}",
style="{")
self.assertEqual(f._fmt,
"$%{message}%$ - {asctime!a:15} - {customfield['key']} - {process:.2f} - {custom.f:.4f}")
f = logging.Formatter("${asctime} - $message", style="$")
self.assertEqual(f._fmt, "${asctime} - $message")

# Testing when ValueError being raised from incorrect format
# Percentage Style
self.assertRaises(ValueError, logging.Formatter, "%(asctime) - 15s")
self.assertRaises(ValueError, logging.Formatter, "%(asctime)Z")
self.assertRaises(ValueError, logging.Formatter, "%(asctime)b")
self.assertRaises(ValueError, logging.Formatter, "%(asctime)*")
self.assertRaises(ValueError, logging.Formatter, "%(asctime)_")
self.assertRaises(ValueError, logging.Formatter, '{asctime}')
self.assertRaises(ValueError, logging.Formatter, '${message}')

Comment thread
vsajip marked this conversation as resolved.
Resolved
# StrFormat Style
self.assertRaises(ValueError, logging.Formatter, "{name-thing}", style="{")
self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='{')
self.assertRaises(ValueError, logging.Formatter, '{asctime!Z:15}', style='{')
self.assertRaises(ValueError, logging.Formatter, '{asctime!aa:15}', style='{')
self.assertRaises(ValueError, logging.Formatter, '{process:.2ff}', style='{')
self.assertRaises(ValueError, logging.Formatter, '{process:.2Z}', style='{')

Comment thread
vsajip marked this conversation as resolved.
Resolved
# Dollar style
self.assertRaises(ValueError, logging.Formatter, '{asctime}', style='$')
self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='$')

Comment thread
vsajip marked this conversation as resolved.
Resolved
def test_invalid_style(self):
self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
Expand Down Expand Up @@ -4000,10 +4035,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 +4067,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.