x/deb-oslo.log
Code Issues Proposed changes

Switch from ContextAdapter to ContextFormatter

Browse Source 
Remove the ContextAdapter and update getLogger to return
KeywordArgumentAdapter instances instead.

Update the JSONFormatter to do some context magic like the
ContextFormatter does so the extra properties from the context and the
KeywordArgumentAdapter are included in the output JSON package.

Update the ContextFormatter to include some nova-specific behavior that
was in ContextAdapter. We will replace that with changes to the way the
default log format strings are constructed in a later patch.

bp/remove-context-adapter

Change-Id: I5a96d55355bf4ef68f2ee71160a3e0200c371e87
This commit is contained in:
Doug Hellmann
2014-09-30 15:09:03 -04:00
parent f41bc13601
commit 1ebed75c1c
3 changed files with 100 additions and 140 deletions
Download Patch File Download Diff File Expand all files Collapse all files

58
oslo/log/formatters.py
View File

@@ -27,12 +27,31 @@ from oslo.serialization import jsonutils
def _dictify_context(context):
if context is None:
return None
return {}
if not isinstance(context, dict) and getattr(context, 'to_dict', None):
context = context.to_dict()
return context
def _update_record_with_context(record):
"""Given a log record, update it with context information.
The request context, if there is one, will either be in the
extra values for the incoming record or in the global
thread-local store.
"""
context = record.__dict__.get(
'context',
getattr(_local.store, 'context', None)
)
d = _dictify_context(context)
# Copy the context values directly onto the record so they can be
# used by the formatting strings.
for k, v in d.items():
setattr(record, k, v)
return context
class JSONFormatter(logging.Formatter):
def __init__(self, fmt=None, datefmt=None):
# NOTE(jkoelker) we ignore the fmt argument, but its still there
@@ -70,8 +89,23 @@ class JSONFormatter(logging.Formatter):
'process': record.process,
'traceback': None}
# Build the extra values that were given to us, including
# the context.
context = _update_record_with_context(record)
if hasattr(record, 'extra'):
message['extra'] = record.extra
extra = record.extra.copy()
else:
extra = {}
for key in getattr(record, 'extra_keys', []):
if key not in extra:
extra[key] = getattr(record, key)
# If we saved a context object, explode it into the extra
# dictionary because the values are more useful than the
# object reference.
if 'context' in extra:
extra.update(_dictify_context(context))
del extra['context']
message['extra'] = extra
if record.exc_info:
message['traceback'] = self.formatException(record.exc_info)
@@ -126,12 +160,22 @@ class ContextFormatter(logging.Formatter):
record.project = self.project
record.version = self.version
# store request info
context = getattr(_local.store, 'context', None)
context = _update_record_with_context(record)
if context:
d = _dictify_context(context)
for k, v in d.items():
setattr(record, k, v)
# FIXME(dhellmann): We should replace these nova-isms with
# more generic handling in the Context class. See the
# app-agnostic-logging-parameters blueprint.
instance = getattr(context, 'instance', None)
instance_uuid = getattr(context, 'instance_uuid', None)
instance_extra = ''
if instance:
instance_extra = (self.conf.instance_format
% {'uuid': instance})
elif instance_uuid:
instance_extra = (self.conf.instance_uuid_format
% {'uuid': instance_uuid})
record.instance = instance_extra
# NOTE(sdague): default the fancier formatting params
# to an empty string so we don't throw an exception if

145
oslo/log/log.py
View File

@@ -43,7 +43,6 @@ from six import moves
_PY26 = sys.version_info[0:2] == (2, 6)
from oslo.log._i18n import _
from oslo.log import _local
from oslo.log import _options
from oslo.log import context as ctx
from oslo.log import formatters
@@ -94,25 +93,6 @@ class BaseLoggerAdapter(logging.LoggerAdapter):
return super(BaseLoggerAdapter, self).isEnabledFor(level)
class LazyAdapter(BaseLoggerAdapter):
def __init__(self, name='unknown', version='unknown'):
self._logger = None
self.extra = {}
self.name = name
self.version = version
@property
def logger(self):
if not self._logger:
self._logger = getLogger(self.name, self.version)
if six.PY3:
# In Python 3, the code fails because the 'manager' attribute
# cannot be found when using a LoggerAdapter as the
# underlying logger. Work around this issue.
self._logger.manager = self._logger.logger.manager
return self._logger
class KeywordArgumentAdapter(BaseLoggerAdapter):
"""Logger adapter to add keyword arguments to log record's extra data
"""
@@ -130,89 +110,23 @@ class KeywordArgumentAdapter(BaseLoggerAdapter):
if name == 'exc_info':
continue
extra[name] = kwargs.pop(name)
# NOTE(dhellmann): The gap between when the adapter is called
# and when the formatter needs to know what the extra values
# are is large enough that we can't get back to the original
# extra dictionary easily. We leave a hint to ourselves here
# in the form of a list of keys, which will eventually be
# attributes of the LogRecord processed by the formatter. That
# allows the formatter to know which values were original and
# which were extra, so it can treat them differently (see
# JSONFormatter for an example of this). We sort the keys so
# it is possible to write sane unit tests.
extra['extra_keys'] = list(sorted(extra.keys()))
# Place the updated extra values back into the keyword
# arguments.
kwargs['extra'] = extra
return msg, kwargs
class ContextAdapter(BaseLoggerAdapter):
warn = logging.LoggerAdapter.warning
def __init__(self, logger, project_name, version_string):
self.logger = logger
self.project = project_name
self.version = version_string
self._deprecated_messages_sent = dict()
@property
def handlers(self):
return self.logger.handlers
def deprecated(self, msg, *args, **kwargs):
"""Call this method when a deprecated feature is used.
If the system is configured for fatal deprecations then the message
is logged at the 'critical' level and :class:`DeprecatedConfig` will
be raised.
Otherwise, the message will be logged (once) at the 'warn' level.
:raises: :class:`DeprecatedConfig` if the system is configured for
fatal deprecations.
"""
stdmsg = _("Deprecated: %s") % msg
if ctx._config.fatal_deprecations:
self.critical(stdmsg, *args, **kwargs)
raise DeprecatedConfig(msg=stdmsg)
# Using a list because a tuple with dict can't be stored in a set.
sent_args = self._deprecated_messages_sent.setdefault(msg, list())
if args in sent_args:
# Already logged this message, so don't log it again.
return
sent_args.append(args)
self.warn(stdmsg, *args, **kwargs)
def process(self, msg, kwargs):
# NOTE(jecarey): If msg is not unicode, coerce it into unicode
# before it can get to the python logging and
# possibly cause string encoding trouble
if not isinstance(msg, six.text_type):
msg = six.text_type(msg)
if 'extra' not in kwargs:
kwargs['extra'] = {}
extra = kwargs['extra']
context = kwargs.pop('context', None)
if not context:
context = getattr(_local.store, 'context', None)
if context:
extra.update(formatters._dictify_context(context))
instance = kwargs.pop('instance', None)
instance_uuid = (extra.get('instance_uuid') or
kwargs.pop('instance_uuid', None))
instance_extra = ''
if instance:
instance_extra = ctx._config.instance_format % instance
elif instance_uuid:
instance_extra = (ctx._config.instance_uuid_format
% {'uuid': instance_uuid})
extra['instance'] = instance_extra
extra.setdefault('user_identity', kwargs.pop('user_identity', None))
extra['project'] = self.project
extra['version'] = self.version
extra['extra'] = extra.copy()
return msg, kwargs
def _create_logging_excepthook(product_name):
def logging_excepthook(exc_type, value, tb):
extra = {'exc_info': (exc_type, value, tb)}
@@ -380,26 +294,21 @@ def _setup_logging_from_conf(conf, project, version):
_loggers = {}
def getLogger(name='unknown', version='unknown'):
if name not in _loggers:
_loggers[name] = ContextAdapter(logging.getLogger(name),
name,
version)
return _loggers[name]
def getLogger(name=None, project='unknown', version='unknown'):
"""Build a logger with the given name.
def getLazyLogger(name='unknown', version='unknown'):
"""Returns lazy logger.
Creates a pass-through logger that does not create the real logger
until it is really needed and delegates all calls to the real logger
once it is created.
:param name: The name for the logger. This is usually the module
name, ``__name__``.
:type name: string
:param project: The name of the project, to be injected into log
messages. For example, ``'nova'``.
:type project: string
:param version: The version of the project, to be injected into log
messages. For example, ``'2014.2'``.
:type version: string
"""
return LazyAdapter(name, version)
class DeprecatedConfig(Exception):
message = _("Fatal call to deprecated config: %(msg)s")
def __init__(self, msg):
super(Exception, self).__init__(self.message % dict(msg=msg))
if name not in _loggers:
_loggers[name] = KeywordArgumentAdapter(logging.getLogger(name),
{'project': project,
'version': version})
return _loggers[name]

37
tests/unit/test_log.py
View File

@@ -106,12 +106,6 @@ class LoggerTestCase(CommonLoggerTestsMixIn, test_base.BaseTestCase):
self.log = log.getLogger(None)
class LazyLoggerTestCase(CommonLoggerTestsMixIn, test_base.BaseTestCase):
def setUp(self):
super(LazyLoggerTestCase, self).setUp()
self.log = log.getLazyLogger(None)
class BaseTestCase(test_base.BaseTestCase):
def setUp(self):
super(BaseTestCase, self).setUp()
@@ -253,11 +247,16 @@ class JSONFormatterTestCase(LogTestBase):
def test_json(self):
test_msg = 'This is a %(test)s line'
test_data = {'test': 'log'}
self.log.debug(test_msg, test_data)
local_context = _fake_context()
self.log.debug(test_msg, test_data, key='value', context=local_context)
data = jsonutils.loads(self.stream.getvalue())
self.assertTrue(data)
self.assertTrue('extra' in data)
extra = data['extra']
self.assertEqual('value', extra['key'])
self.assertEqual(local_context.auth_token, extra['auth_token'])
self.assertEqual(local_context.user, extra['user'])
self.assertEqual('test-json', data['name'])
self.assertEqual(test_msg % test_data, data['message'])
@@ -710,19 +709,20 @@ class KeywordArgumentAdapterTestCase(BaseTestCase):
def test_empty_kwargs(self):
a = log.KeywordArgumentAdapter(self.mock_log, {})
msg, kwargs = a.process('message', {})
self.assertEqual(kwargs, {'extra': {}})
self.assertEqual(kwargs, {'extra': {'extra_keys': []}})
def test_include_constructor_extras(self):
a = log.KeywordArgumentAdapter(self.mock_log, {'foo': 'blah'})
msg, kwargs = a.process('message', {})
self.assertEqual(kwargs, {'extra': {'foo': 'blah'}})
self.assertEqual(kwargs,
{'extra': {'foo': 'blah', 'extra_keys': ['foo']}})
def test_pass_through_exc_info(self):
a = log.KeywordArgumentAdapter(self.mock_log, {})
msg, kwargs = a.process('message', {'exc_info': 'the info'})
self.assertEqual(
kwargs,
{'extra': {},
{'extra': {'extra_keys': []},
'exc_info': 'the info'},
)
@@ -736,7 +736,10 @@ class KeywordArgumentAdapterTestCase(BaseTestCase):
)
self.assertEqual(
kwargs,
{'extra': {'context': 'some context object',
{'extra': {'anything': 'goes',
'context': 'some context object',
'extra_keys': ['anything', 'context',
'instance', 'instance_uuid'],
'instance': 'instance identifier',
'instance_uuid': 'UUID for instance',
'anything': 'goes'}},
@@ -750,14 +753,16 @@ class KeywordArgumentAdapterTestCase(BaseTestCase):
logging.DEBUG,
'message',
(),
extra={'name': 'value'},
extra={'name': 'value',
'extra_keys': ['name']},
exc_info='exception',
)
else:
self.mock_log.log.assert_called_once_with(
logging.DEBUG,
'message',
extra={'name': 'value'},
extra={'name': 'value',
'extra_keys': ['name']},
exc_info='exception',
)
@@ -772,12 +777,14 @@ class KeywordArgumentAdapterTestCase(BaseTestCase):
logging.DEBUG,
'message',
(),
extra={'name': 'value'},
extra={'name': 'value',
'extra_keys': ['name']},
exc_info='exception',
)
else:
self.mock_log.debug.assert_called_once_with(
'message',
extra={'name': 'value'},
extra={'name': 'value',
'extra_keys': ['name']},
exc_info='exception',
)