From 14088fb6e43676b2bfbbcd96bc78740ee862c550 Mon Sep 17 00:00:00 2001 From: Sean Dague Date: Fri, 27 Jul 2012 17:22:58 -0400 Subject: 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 --- openstack/common/log.py | 8 ++++++-- tests/unit/test_log.py | 54 +++++++++++++++++++++++++++++++++++++++++++++++++ 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()) -- cgit