Merge pull request #65 from zopefoundation/fd-logger-arbitrary-fields

support arbitrary field names in format strings

CHANGES.rst

@@ -5,15 +5,30 @@ Change History for ZConfig
 3.4.0 (unreleased)
 ------------------
 
-- The ``logfile`` section type defined by the ``ZConfig.components.logger``
-  package supports an optional ``style`` parameter.  This can be used to
-  configure alternate format styles as found in the Python 3 standard
-  library.  Four ``style`` values are supported: ``classic`` (the
-  default), ``format`` (equivalent to ``style='{'`` in Python 3),
-  ``template`` (equivalent to ``style='$'``), and ``safe-template``
-  (similar to ``template``, but using the ``string.Template`` method
-  ``safe_substitute`` method).  A best-effort implementation is provided
-  for Python 2.
+Many changes have been made in the support for logging configurations:
+
+- The log handler section types defined by the
+  ``ZConfig.components.logger`` package support additional, optional
+  parameters:
+
+  ``style``
+      Used to configure alternate format styles as found in the Python 3
+      standard library.  Four ``style`` values are supported:
+      ``classic`` (the default), ``format`` (equivalent to ``style='{'``
+      in Python 3), ``template`` (equivalent to ``style='$'``), and
+      ``safe-template`` (similar to ``template``, but using the
+      ``string.Template`` method ``safe_substitute`` method).  A
+      best-effort implementation is provided for Python 2.
+
+  ``arbitrary-fields``
+      A Boolean defauting to ``False`` for backward compatibility,
+      allows arbitrary replacement field names to be accepted in the
+      format string (regardless of the ``style`` setting).  This
+      supports applications where log records are known to be generated
+      with additional string or numeric fields, at least for some
+      loggers.  (An exception is still raised at format time if the
+      additional fields are not provided, unless the ``style`` value
+      ``safe-template`` is used.)
 
 - The ``logfile`` section type defined by the ``ZConfig.components.logger``
   package supports the optional ``delay`` and ``encoding`` parameters.

ZConfig/components/logger/formatter.py

@@ -24,6 +24,22 @@
 import ZConfig._compat
 
 
+if sys.version_info[0] == 2:
+
+    class StringFormatter(string.Formatter):
+
+        def get_field(self, field_name, args, kwargs):
+            if field_name == '':
+                # Not correctly supported in Python 2 string.Formatter;
+                # KeyError is raised instead of IndexError for the
+                # computed index.
+                raise IndexError('tuple index out of range')
+            return string.Formatter.get_field(self, field_name, args, kwargs)
+
+else:
+    StringFormatter = string.Formatter
+
+
 class PercentStyle(object):
 
     logging_style = '%'
@@ -48,8 +64,10 @@ class StrFormatStyle(PercentStyle):
     asctime_format = '{asctime}'
     asctime_search = '{asctime'
 
+    __formatter = StringFormatter()
+
     def format(self, record):
-        return self._fmt.format(**record.__dict__)
+        return self.__formatter.vformat(self._fmt, (), record.__dict__)
 
 
 class StringTemplateStyle(PercentStyle):
@@ -68,15 +86,15 @@ 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__)
+        return self._tpl.substitute(record.__dict__)
 
 
 class SafeStringTemplateStyle(StringTemplateStyle):
 
     logging_style = None
 
     def format(self, record):
-        return self._tpl.safe_substitute(**record.__dict__)
+        return self._tpl.safe_substitute(record.__dict__)
 
 
 _control_char_rewrites = {r'\n': '\n', r'\t': '\t', r'\b': '\b',
@@ -142,6 +160,24 @@ def resolve(name):
     return found
 
 
+class AnyFieldDict(dict):
+    # Only used for format string validation.
+
+    def __getitem__(self, key):
+        if key in self:
+            # Avoid magic for known keys; better to provide a sample
+            # value of an appropriate type when there is such a thing.
+            return dict.__getitem__(self, key)
+        else:
+            # Using an int as the default works with "reasonable" values
+            # that might be formatted in a logging configuration:
+            #
+            # - str/repr are safe
+            # - numeric formatting is safe, allowing for casting to float
+            #
+            return 42
+
+
 class FormatterFactory(object):
 
     def __init__(self, section):
@@ -179,6 +215,10 @@ def __init__(self, section):
         record = logging.LogRecord(__name__, logging.INFO, __file__,
                                    42, 'some message', (), None)
         record.__dict__.update(_log_format_variables)
+        if section.arbitrary_fields:
+            fields = AnyFieldDict()
+            fields.update(record.__dict__)
+            record.__dict__ = fields
         try:
             self.stylist.format(record)
         except IndexError:

ZConfig/components/logger/handlers.xml

@@ -62,6 +62,21 @@
         ``template``, or ``safe-template``.
       </description>
     </key>
+    <key name="arbitrary-fields"
+         default="false"
+         datatype="boolean">
+      <description>
+        If true, allow arbitrary fields in the log record object to be
+        referenced from the ``format`` value.
+
+        This does not cause references to fields not present in the log
+        record to be accepted; it only means unknown fields will not
+        cause configuration of the formatter to be denied.
+
+        To get both effects, set this to ``true`` and use a ``style`` of
+        ``safe-template``.
+      </description>
+    </key>
   </sectiontype>
 
   <sectiontype name="logfile"

ZConfig/components/logger/tests/test_formatter.py

@@ -100,22 +100,28 @@ def setUp(self):
         self.record.x1 = 24
         self.record.x2 = 37
 
-    def get_logger_factory(self, style=None, format=None):
+    def get_logger_factory(self, style=None, format=None,
+                           arbitrary_fields=False):
         formatter_lines = []
         if style:
             formatter_lines.append('style %s' % style)
         if format:
             formatter_lines.append('format %s' % format)
+        if arbitrary_fields:
+            formatter_lines.append('arbitrary-fields true')
         formatter_config = '\n    '.join(formatter_lines)
         parsed = self.get_config(self._config_template % formatter_config)
         return parsed.eventlog
 
-    def get_formatter_factory(self, style=None, format=None):
-        logger_factory = self.get_logger_factory(style=style, format=format)
+    def get_formatter_factory(self, style=None, format=None,
+                              arbitrary_fields=False):
+        logger_factory = self.get_logger_factory(
+            style=style, format=format, arbitrary_fields=arbitrary_fields)
         return logger_factory.handler_factories[0].create_formatter
 
-    def get_formatter(self, style=None, format=None):
-        factory = self.get_formatter_factory(style=style, format=format)
+    def get_formatter(self, style=None, format=None, arbitrary_fields=False):
+        factory = self.get_formatter_factory(
+            style=style, format=format, arbitrary_fields=arbitrary_fields)
         return factory()
 
 
@@ -490,3 +496,117 @@ def test_relative_created_float_format(self):
         self.record.relativeCreated = 406.7840576171875
         output = formatter.format(self.record)
         self.assertIn('+406.784 WARNING my message', output)
+
+
+class ArbitraryFieldsTestCase(StyledFormatterTestHelper, unittest.TestCase):
+
+    def test_classic_arbitrary_field_disallowed_by_default(self):
+        with self.assertRaises(KeyError) as cm:
+            self.get_formatter_factory(
+                style='classic',
+                format='%(levelno)s %(levelname)s %(undefined_field)s')
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    def test_format_arbitrary_field_disallowed_by_default(self):
+        with self.assertRaises(KeyError) as cm:
+            self.get_formatter_factory(
+                style='format',
+                format='{levelno} {levelname} {undefined_field}')
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    def test_template_arbitrary_field_disallowed_by_default(self):
+        with self.assertRaises(KeyError) as cm:
+            self.get_formatter_factory(
+                style='format',
+                format='$${levelno} $${levelname} $${undefined_field}')
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    # We don't need to check the safe-template variety, because it's
+    # highly permissive.
+
+    def test_classic_arbitrary_field_missing(self):
+        formatter = self.get_formatter(
+            style='classic',
+            format='%(levelno)s %(levelname)s %(undefined_field)s',
+            arbitrary_fields=True)
+
+        # The formatter still breaks when it references an undefined field:
+        with self.assertRaises(KeyError) as cm:
+            formatter.format(self.record)
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    def test_classic_arbitrary_field_present(self):
+        formatter = self.get_formatter(
+            style='classic',
+            format='%(levelno)s %(levelname)s %(undefined_field)s',
+            arbitrary_fields=True)
+
+        # Given the field, it formats just fine:
+        self.record.undefined_field = 'surprise!'
+        logentry = formatter.format(self.record)
+        self.assertIn('surprise!', logentry)
+
+    def test_format_arbitrary_field_missing(self):
+        formatter = self.get_formatter(
+            style='format',
+            format='{levelno} {levelname} {undefined_field}',
+            arbitrary_fields=True)
+
+        # The formatter still breaks when it references an undefined field:
+        with self.assertRaises(KeyError) as cm:
+            formatter.format(self.record)
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    def test_format_arbitrary_field_present(self):
+        formatter = self.get_formatter(
+            style='format',
+            format='{levelno} {levelname} {undefined_field}',
+            arbitrary_fields=True)
+
+        # Given the field, it formats just fine:
+        self.record.undefined_field = 'surprise!'
+        logentry = formatter.format(self.record)
+        self.assertIn('surprise!', logentry)
+
+    def test_template_arbitrary_field_missing(self):
+        formatter = self.get_formatter(
+            style='template',
+            format='$${levelno} $${levelname} $${undefined_field}',
+            arbitrary_fields=True)
+
+        # The formatter still breaks when it references an undefined field:
+        with self.assertRaises(KeyError) as cm:
+            formatter.format(self.record)
+        self.assertEqual(str(cm.exception), "'undefined_field'")
+
+    def test_template_arbitrary_field_present(self):
+        formatter = self.get_formatter(
+            style='template',
+            format='$${levelno} $${levelname} $${undefined_field}',
+            arbitrary_fields=True)
+
+        # Given the field, it formats just fine:
+        self.record.undefined_field = 'surprise!'
+        logentry = formatter.format(self.record)
+        self.assertIn('surprise!', logentry)
+
+    def test_safe_template_arbitrary_field_missing(self):
+        formatter = self.get_formatter(
+            style='safe-template',
+            format='$${levelno} $${levelname} $${undefined_field}',
+            arbitrary_fields=True)
+
+        # The formatter still breaks when it references an undefined field:
+        logentry = formatter.format(self.record)
+        self.assertIn(' ${undefined_field}', logentry)
+
+    def test_safe_template_arbitrary_field_present(self):
+        formatter = self.get_formatter(
+            style='safe-template',
+            format='$${levelno} $${levelname} $${undefined_field}',
+            arbitrary_fields=True)
+
+        # Given the field, it formats just fine:
+        self.record.undefined_field = 'surprise!'
+        logentry = formatter.format(self.record)
+        self.assertIn('surprise!', logentry)