diff options
| -rw-r--r-- | Doc/library/logging.config.rst | 5 | ||||
| -rw-r--r-- | Doc/library/logging.rst | 4 | ||||
| -rw-r--r-- | Lib/logging/__init__.py | 68 | ||||
| -rw-r--r-- | Lib/logging/config.py | 10 | ||||
| -rw-r--r-- | Lib/test/test_logging.py | 332 | ||||
| -rw-r--r-- | Misc/NEWS.d/next/Library/2018-10-04-20-44-45.bpo-34844.Hnuxav.rst | 6 |
6 files changed, 403 insertions, 22 deletions
diff --git a/Doc/library/logging.config.rst b/Doc/library/logging.config.rst index de805eb..7f6c3c6 100644 --- a/Doc/library/logging.config.rst +++ b/Doc/library/logging.config.rst @@ -226,6 +226,11 @@ otherwise, the context is used to determine what to instantiate. (with defaults of ``None``) and these are used to construct a :class:`~logging.Formatter` instance. + .. versionchanged:: 3.8 + a ``validate`` key (with default of ``True``) can be added into + the ``formatters`` section of the configuring dict, this is to + validate the format. + * *filters* - the corresponding value will be a dict in which each key is a filter id and each value is a dict describing how to configure the corresponding Filter instance. diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index c63ea21..71a46ac 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -544,6 +544,10 @@ The useful mapping keys in a :class:`LogRecord` are given in the section on .. versionchanged:: 3.2 The *style* parameter was added. + .. versionchanged:: 3.8 + The *validate* parameter was added. Incorrect or mismatched style and fmt + will raise a ``ValueError``. + For example: ``logging.Formatter('%(asctime)s - %(message)s', style='{')``. .. method:: format(record) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 7aeff45..58afcd2 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -23,9 +23,11 @@ Copyright (C) 2001-2017 Vinay Sajip. All Rights Reserved. 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 string import Formatter as StrFormatter + __all__ = ['BASIC_FORMAT', 'BufferingFormatter', 'CRITICAL', 'DEBUG', 'ERROR', 'FATAL', 'FileHandler', 'Filter', 'Formatter', 'Handler', 'INFO', @@ -413,15 +415,20 @@ def makeLogRecord(dict): rv.__dict__.update(dict) return rv + #--------------------------------------------------------------------------- # Formatter classes and functions #--------------------------------------------------------------------------- +_str_formatter = StrFormatter() +del StrFormatter + class PercentStyle(object): default_format = '%(message)s' asctime_format = '%(asctime)s' asctime_search = '%(asctime)' + validation_pattern = re.compile(r'%\(\w+\)[#0+ -]*(\*|\d+)?(\.(\*|\d+))?[diouxefgcrsa%]', re.I) def __init__(self, fmt): self._fmt = fmt or self.default_format @@ -429,17 +436,50 @@ class PercentStyle(object): def usesTime(self): return self._fmt.find(self.asctime_search) >= 0 - def format(self, record): + def validate(self): + """Validate the input format, ensure it matches the correct style""" + if not self.validation_pattern.search(self._fmt): + raise ValueError("Invalid format '%s' for '%s' style" % (self._fmt, self.default_format[0])) + + def _format(self, record): return self._fmt % record.__dict__ + def format(self, record): + try: + return self._format(record) + except KeyError as e: + raise ValueError('Formatting field not found in record: %s' % e) + + class StrFormatStyle(PercentStyle): default_format = '{message}' asctime_format = '{asctime}' asctime_search = '{asctime' - def format(self, record): + fmt_spec = re.compile(r'^(.?[<>=^])?[+ -]?#?0?(\d+|{\w+})?[,_]?(\.(\d+|{\w+}))?[bcdefgnosx%]?$', re.I) + field_spec = re.compile(r'^(\d+|\w+)(\.\w+|\[[^]]+\])*$') + + def _format(self, record): return self._fmt.format(**record.__dict__) + def validate(self): + """Validate the input format, ensure it is the correct string formatting style""" + fields = set() + try: + for _, fieldname, spec, conversion in _str_formatter.parse(self._fmt): + if fieldname: + if not self.field_spec.match(fieldname): + raise ValueError('invalid field name/expression: %r' % fieldname) + fields.add(fieldname) + if conversion and conversion not in 'rsa': + raise ValueError('invalid conversion: %r' % conversion) + if spec and not self.fmt_spec.match(spec): + raise ValueError('bad specifier: %r' % spec) + except ValueError as e: + raise ValueError('invalid format: %s' % e) + if not fields: + raise ValueError('invalid format: no fields') + class StringTemplateStyle(PercentStyle): default_format = '${message}' @@ -454,9 +494,24 @@ class StringTemplateStyle(PercentStyle): fmt = self._fmt return fmt.find('$asctime') >= 0 or fmt.find(self.asctime_format) >= 0 - def format(self, record): + def validate(self): + pattern = Template.pattern + fields = set() + for m in pattern.finditer(self._fmt): + d = m.groupdict() + if d['named']: + fields.add(d['named']) + elif d['braced']: + fields.add(d['braced']) + elif m.group(0) == '$': + raise ValueError('invalid format: bare \'$\' not allowed') + if not fields: + raise ValueError('invalid format: no fields') + + def _format(self, record): return self._tpl.substitute(**record.__dict__) + BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s" _STYLES = { @@ -510,7 +565,7 @@ class Formatter(object): converter = time.localtime - def __init__(self, fmt=None, datefmt=None, style='%'): + def __init__(self, fmt=None, datefmt=None, style='%', validate=True): """ Initialize the formatter with specified format strings. @@ -530,6 +585,9 @@ class Formatter(object): raise ValueError('Style must be one of: %s' % ','.join( _STYLES.keys())) self._style = _STYLES[style][0](fmt) + if validate: + self._style.validate() + self._fmt = self._style._fmt self.datefmt = datefmt diff --git a/Lib/logging/config.py b/Lib/logging/config.py index fa1a398..cfd9311 100644 --- a/Lib/logging/config.py +++ b/Lib/logging/config.py @@ -666,11 +666,19 @@ class DictConfigurator(BaseConfigurator): dfmt = config.get('datefmt', None) style = config.get('style', '%') cname = config.get('class', None) + if not cname: c = logging.Formatter else: c = _resolve(cname) - result = c(fmt, dfmt, style) + + # A TypeError would be raised if "validate" key is passed in with a formatter callable + # that does not accept "validate" as a parameter + if 'validate' in config: # if user hasn't mentioned it, the default will be fine + result = c(fmt, dfmt, style, config['validate']) + else: + result = c(fmt, dfmt, style) + return result def configure_filter(self, config): diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index d352e5f..9802955 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -2125,6 +2125,10 @@ class WarningsTest(BaseTest): def formatFunc(format, datefmt=None): return logging.Formatter(format, datefmt) +class myCustomFormatter: + def __init__(self, fmt, datefmt=None): + pass + def handlerFunc(): return logging.StreamHandler() @@ -2765,6 +2769,114 @@ class ConfigDictTest(BaseTest): } } + # Configuration with custom logging.Formatter subclass as '()' key and 'validate' set to False + custom_formatter_class_validate = { + 'version': 1, + 'formatters': { + 'form1': { + '()': __name__ + '.ExceptionFormatter', + 'format': '%(levelname)s:%(name)s:%(message)s', + 'validate': False, + }, + }, + 'handlers' : { + 'hand1' : { + 'class': 'logging.StreamHandler', + 'formatter': 'form1', + 'level': 'NOTSET', + 'stream': 'ext://sys.stdout', + }, + }, + "loggers": { + "my_test_logger_custom_formatter": { + "level": "DEBUG", + "handlers": ["hand1"], + "propagate": "true" + } + } + } + + # Configuration with custom logging.Formatter subclass as 'class' key and 'validate' set to False + custom_formatter_class_validate2 = { + 'version': 1, + 'formatters': { + 'form1': { + 'class': __name__ + '.ExceptionFormatter', + 'format': '%(levelname)s:%(name)s:%(message)s', + 'validate': False, + }, + }, + 'handlers' : { + 'hand1' : { + 'class': 'logging.StreamHandler', + 'formatter': 'form1', + 'level': 'NOTSET', + 'stream': 'ext://sys.stdout', + }, + }, + "loggers": { + "my_test_logger_custom_formatter": { + "level": "DEBUG", + "handlers": ["hand1"], + "propagate": "true" + } + } + } + + # Configuration with custom class that is not inherited from logging.Formatter + custom_formatter_class_validate3 = { + 'version': 1, + 'formatters': { + 'form1': { + 'class': __name__ + '.myCustomFormatter', + 'format': '%(levelname)s:%(name)s:%(message)s', + 'validate': False, + }, + }, + 'handlers' : { + 'hand1' : { + 'class': 'logging.StreamHandler', + 'formatter': 'form1', + 'level': 'NOTSET', + 'stream': 'ext://sys.stdout', + }, + }, + "loggers": { + "my_test_logger_custom_formatter": { + "level": "DEBUG", + "handlers": ["hand1"], + "propagate": "true" + } + } + } + + # Configuration with custom function and 'validate' set to False + custom_formatter_with_function = { + 'version': 1, + 'formatters': { + 'form1': { + '()': formatFunc, + 'format': '%(levelname)s:%(name)s:%(message)s', + 'validate': False, + }, + }, + 'handlers' : { + 'hand1' : { + 'class': 'logging.StreamHandler', + 'formatter': 'form1', + 'level': 'NOTSET', + 'stream': 'ext://sys.stdout', + }, + }, + "loggers": { + "my_test_logger_custom_formatter": { + "level": "DEBUG", + "handlers": ["hand1"], + "propagate": "true" + } + } + } + def apply_config(self, conf): logging.config.dictConfig(conf) @@ -3163,12 +3275,43 @@ class ConfigDictTest(BaseTest): ], 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, logging.StringTemplateStyle) + def test_custom_formatter_class_with_validate(self): + self.apply_config(self.custom_formatter_class_validate) + handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0] + self.assertIsInstance(handler.formatter, ExceptionFormatter) + + def test_custom_formatter_class_with_validate2(self): + self.apply_config(self.custom_formatter_class_validate2) + handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0] + self.assertIsInstance(handler.formatter, ExceptionFormatter) + + def test_custom_formatter_class_with_validate2_with_wrong_fmt(self): + config = self.custom_formatter_class_validate.copy() + config['formatters']['form1']['style'] = "$" + + # Exception should not be raise as we have configured 'validate' to False + self.apply_config(config) + handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0] + self.assertIsInstance(handler.formatter, ExceptionFormatter) + + def test_custom_formatter_class_with_validate3(self): + self.assertRaises(ValueError, self.apply_config, self.custom_formatter_class_validate3) + + def test_custom_formatter_function_with_validate(self): + self.assertRaises(ValueError, self.apply_config, self.custom_formatter_with_function) + def test_baseconfig(self): d = { 'atuple': (1, 2, 3), @@ -3485,20 +3628,26 @@ class FormatterTest(unittest.TestCase): result.update(self.variants[name]) return logging.makeLogRecord(result) + def assert_error_message(self, exception, message, *args, **kwargs): + try: + self.assertRaises(exception, *args, **kwargs) + except exception as e: + self.assertEqual(message, e.message) + def test_percent(self): # Test %-formatting r = self.get_record() 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): # Test {}-formatting @@ -3506,7 +3655,8 @@ class FormatterTest(unittest.TestCase): 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()) @@ -3514,27 +3664,177 @@ class FormatterTest(unittest.TestCase): 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='$') + 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('$$%${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='$') - 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='$') + self.assertTrue(f.usesTime()) + + def test_format_validate(self): + # Check correct formatting + # Percentage style + f = logging.Formatter("%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s") + self.assertEqual(f._fmt, "%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s") + f = logging.Formatter("%(asctime)*s - %(asctime)*.3s - %(process)-34.33o") + self.assertEqual(f._fmt, "%(asctime)*s - %(asctime)*.3s - %(process)-34.33o") + f = logging.Formatter("%(process)#+027.23X") + self.assertEqual(f._fmt, "%(process)#+027.23X") + f = logging.Formatter("%(foo)#.*g") + self.assertEqual(f._fmt, "%(foo)#.*g") + + # StrFormat Style + f = logging.Formatter("$%{message}%$ - {asctime!a:15} - {customfield['key']}", style="{") + self.assertEqual(f._fmt, "$%{message}%$ - {asctime!a:15} - {customfield['key']}") + f = logging.Formatter("{process:.2f} - {custom.f:.4f}", style="{") + self.assertEqual(f._fmt, "{process:.2f} - {custom.f:.4f}") + f = logging.Formatter("{customfield!s:#<30}", style="{") + self.assertEqual(f._fmt, "{customfield!s:#<30}") + f = logging.Formatter("{message!r}", style="{") + self.assertEqual(f._fmt, "{message!r}") + f = logging.Formatter("{message!s}", style="{") + self.assertEqual(f._fmt, "{message!s}") + f = logging.Formatter("{message!a}", style="{") + self.assertEqual(f._fmt, "{message!a}") + f = logging.Formatter("{process!r:4.2}", style="{") + self.assertEqual(f._fmt, "{process!r:4.2}") + f = logging.Formatter("{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}", style="{") + self.assertEqual(f._fmt, "{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}") + f = logging.Formatter("{process!s:{w},.{p}}", style="{") + self.assertEqual(f._fmt, "{process!s:{w},.{p}}") + f = logging.Formatter("{foo:12.{p}}", style="{") + self.assertEqual(f._fmt, "{foo:12.{p}}") + f = logging.Formatter("{foo:{w}.6}", style="{") + self.assertEqual(f._fmt, "{foo:{w}.6}") + f = logging.Formatter("{foo[0].bar[1].baz}", style="{") + self.assertEqual(f._fmt, "{foo[0].bar[1].baz}") + f = logging.Formatter("{foo[k1].bar[k2].baz}", style="{") + self.assertEqual(f._fmt, "{foo[k1].bar[k2].baz}") + f = logging.Formatter("{12[k1].bar[k2].baz}", style="{") + self.assertEqual(f._fmt, "{12[k1].bar[k2].baz}") + + # Dollar style + f = logging.Formatter("${asctime} - $message", style="$") + self.assertEqual(f._fmt, "${asctime} - $message") + f = logging.Formatter("$bar $$", style="$") + self.assertEqual(f._fmt, "$bar $$") + f = logging.Formatter("$bar $$$$", style="$") + self.assertEqual(f._fmt, "$bar $$$$") # this would print two $($$) + + # Testing when ValueError being raised from incorrect format + # Percentage Style + 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)*3s") + self.assertRaises(ValueError, logging.Formatter, "%(asctime)_") + self.assertRaises(ValueError, logging.Formatter, '{asctime}') + self.assertRaises(ValueError, logging.Formatter, '${message}') + self.assertRaises(ValueError, logging.Formatter, '%(foo)#12.3*f') # with both * and decimal number as precision + self.assertRaises(ValueError, logging.Formatter, '%(foo)0*.8*f') + + # StrFormat Style + # Testing failure for '-' in field name + self.assert_error_message( + ValueError, + "invalid field name/expression: 'name-thing'", + logging.Formatter, "{name-thing}", style="{" + ) + # Testing failure for style mismatch + self.assert_error_message( + ValueError, + "invalid format: no fields", + logging.Formatter, '%(asctime)s', style='{' + ) + # Testing failure for invalid conversion + self.assert_error_message( + ValueError, + "invalid conversion: 'Z'" + ) + self.assertRaises(ValueError, logging.Formatter, '{asctime!s:#30,15f}', style='{') + self.assert_error_message( + ValueError, + "invalid format: expected ':' after conversion specifier", + logging.Formatter, '{asctime!aa:15}', style='{' + ) + # Testing failure for invalid spec + self.assert_error_message( + ValueError, + "bad specifier: '.2ff'", + logging.Formatter, '{process:.2ff}', style='{' + ) + self.assertRaises(ValueError, logging.Formatter, '{process:.2Z}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{process!s:<##30,12g}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{process!s:<#30#,12g}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{process!s:{{w}},{{p}}}', style='{') + # Testing failure for mismatch braces + self.assert_error_message( + ValueError, + "invalid format: unmatched '{' in format spec", + logging.Formatter, '{process', style='{' + ) + self.assert_error_message( + ValueError, + "invalid format: unmatched '{' in format spec", + logging.Formatter, 'process}', style='{' + ) + self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo/bar}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo:{{w}}.{{p}}}}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo!X:{{w}}.{{p}}}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo!a:random}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{dom}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{d}om}', style='{') + self.assertRaises(ValueError, logging.Formatter, '{foo.!a:d}', style='{') + + # Dollar style + # Testing failure for mismatch bare $ + self.assert_error_message( + ValueError, + "invalid format: bare \'$\' not allowed", + logging.Formatter, '$bar $$$', style='$' + ) + self.assert_error_message( + ValueError, + "invalid format: bare \'$\' not allowed", + logging.Formatter, 'bar $', style='$' + ) + self.assert_error_message( + ValueError, + "invalid format: bare \'$\' not allowed", + logging.Formatter, 'foo $.', style='$' + ) + # Testing failure for mismatch style + self.assert_error_message( + ValueError, + "invalid format: no fields", + logging.Formatter, '{asctime}', style='$' + ) + self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='$') + + # Testing failure for incorrect fields + self.assert_error_message( + ValueError, + "invalid format: no fields", + logging.Formatter, 'foo', style='$' + ) + self.assertRaises(ValueError, logging.Formatter, '${asctime', style='$') def test_invalid_style(self): self.assertRaises(ValueError, logging.Formatter, None, None, 'x') @@ -4000,10 +4300,10 @@ class BasicConfigTest(unittest.TestCase): 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') @@ -4032,11 +4332,11 @@ class BasicConfigTest(unittest.TestCase): 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 diff --git a/Misc/NEWS.d/next/Library/2018-10-04-20-44-45.bpo-34844.Hnuxav.rst b/Misc/NEWS.d/next/Library/2018-10-04-20-44-45.bpo-34844.Hnuxav.rst new file mode 100644 index 0000000..464dcb1 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2018-10-04-20-44-45.bpo-34844.Hnuxav.rst @@ -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. |