don't throw exceptions if %(color)s tag is used

fixed bug #1030078

If the log format strings include the %(color)s key in them and you
enable file logging, your log files won't work, and instead you'll
see exceptions on the console as the default python log handler doesn't
support that keyword.

This approach stubs out the extra keywords to be empty strings to avoid
the KeyError. Tests are also added to demonstrate the KeyError as defined
behavior, and test that color codes can be passed.

Change-Id: Ia5dbaee9c530e243e2121667c8a54e6f9d66e1e7

2 files changed, 60 insertions, 2 deletions

diff --git a/openstack/common/log.py b/openstack/common/log.py
index 8a368a1..5f0478f 100644
--- a/openstack/common/log.py
+++ b/openstack/common/log.py
@@ -405,8 +405,12 @@ class LegacyFormatter(logging.Formatter):
 
     def format(self, record):
         """Uses contextstring if request_id is set, otherwise default."""
-        if 'instance' not in record.__dict__:
-            record.__dict__['instance'] = ''
+        # NOTE(sdague): default the fancier formating params
+        # to an empty string so we don't throw an exception if
+        # they get used
+        for key in ('instance', 'color'):
+            if key not in record.__dict__:
+                record.__dict__[key] = ''
 
         if record.__dict__.get('request_id', None):
             self._fmt = CONF.logging_context_format_string
diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py
index 83c318f..c4ce75b 100644
--- a/tests/unit/test_log.py
+++ b/tests/unit/test_log.py
@@ -1,4 +1,5 @@
 import cStringIO
+import exceptions
 import logging
 import sys
 
@@ -216,3 +217,56 @@ class LegacyFormatterTestCase(test_utils.BaseTestCase):
     def test_debugging_log(self):
         self.log.debug("baz")
         self.assertEqual("NOCTXT: baz --DBG\n", self.stream.getvalue())
+
+
+class FancyRecordTestCase(test_utils.BaseTestCase):
+    """Test how we handle fancy record keys that are not in the
+    base python logging"""
+
+    def setUp(self):
+        super(FancyRecordTestCase, self).setUp()
+        # NOTE(sdague): use the different formatters to demonstrate format
+        # string with valid fancy keys and without. Slightly hacky, but given
+        # the way log objects layer up seemed to be most concise approach
+        self.config(logging_context_format_string="%(color)s "
+                                                  "[%(request_id)s]: "
+                                                  "%(message)s",
+                    logging_default_format_string="%(missing)s: %(message)s")
+        self.stream = cStringIO.StringIO()
+
+        self.colorhandler = log.ColorHandler(self.stream)
+        self.colorhandler.setFormatter(log.LegacyFormatter())
+
+        self.colorlog = log.getLogger()
+        self.colorlog.logger.addHandler(self.colorhandler)
+        self.level = self.colorlog.logger.getEffectiveLevel()
+        self.colorlog.logger.setLevel(logging.DEBUG)
+
+    def test_unsupported_key_in_log_msg(self):
+        # NOTE(sdague): exception logging bypasses the main stream
+        # and goes to stderr. Suggests on a better way to do this are
+        # welcomed.
+        error = sys.stderr
+        sys.stderr = cStringIO.StringIO()
+
+        self.colorlog.info("foo")
+        self.assertNotEqual(sys.stderr.getvalue().find("KeyError: 'missing'"),
+                           -1)
+
+        sys.stderr = error
+
+    def test_fancy_key_in_log_msg(self):
+        ctxt = _fake_context()
+
+        # TODO(sdague): there should be a way to retrieve this from the
+        # color handler
+        infocolor = '\033[00;36m'
+        warncolor = '\033[01;33m'
+        infoexpected = "%s [%s]: info\n" % (infocolor, ctxt.request_id)
+        warnexpected = "%s [%s]: warn\n" % (warncolor, ctxt.request_id)
+
+        self.colorlog.info("info", context=ctxt)
+        self.assertEqual(infoexpected, self.stream.getvalue())
+
+        self.colorlog.warn("warn", context=ctxt)
+        self.assertEqual(infoexpected + warnexpected, self.stream.getvalue())