Optimize log formatting

There is no way to change the configuration variables we want
printed in log messages, so format them in the constructor.
This will save us from overridding the format method and
a couple cpu cycles every log message.  This change also moves
the _LOG* variables into the formatter since they aren't really
globally needed.

Change-Id: I706e9db7da3daec20332f9d1533fe665f2739dea
Implements: blueprint logging-migration
This commit is contained in:
TerryHowe 2015-08-09 07:31:34 -06:00 committed by Terry Howe
parent d828429d6a
commit 6c46355734
2 changed files with 58 additions and 90 deletions

View File

@ -16,11 +16,6 @@
import logging
import warnings
_LOG_MESSAGE_FORMAT = ('%(asctime)s.%(msecs)03d %(process)d '
'%(levelname)s %(name)s [%(clouds_name)s '
'%(username)s %(project_name)s] %(message)s')
_LOG_DATE_FORMAT = '%Y-%m-%d %H:%M:%S'
def log_level_from_options(options):
# if --debug, --quiet or --verbose is not specified,
@ -73,6 +68,37 @@ def set_warning_filter(log_level):
warnings.simplefilter("once")
class _FileFormatter(logging.Formatter):
"""Customize the logging format for logging handler"""
_LOG_MESSAGE_BEGIN = (
'%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s ')
_LOG_MESSAGE_CONTEXT = '[%(cloud)s %(username)s %(project)s] '
_LOG_MESSAGE_END = '%(message)s'
_LOG_DATE_FORMAT = '%Y-%m-%d %H:%M:%S'
def __init__(self, options=None, config=None, **kwargs):
context = {}
if options:
context = {
'cloud': getattr(options, 'cloud', ''),
'project': getattr(options, 'os_project_name', ''),
'username': getattr(options, 'username', ''),
}
elif config:
context = {
'cloud': config.config.get('cloud', ''),
'project': config.auth.get('project_name', ''),
'username': config.auth.get('username', ''),
}
if context:
self.fmt = (self._LOG_MESSAGE_BEGIN +
(self._LOG_MESSAGE_CONTEXT % context) +
self._LOG_MESSAGE_END)
else:
self.fmt = self._LOG_MESSAGE_BEGIN + self._LOG_MESSAGE_END
logging.Formatter.__init__(self, self.fmt, self._LOG_DATE_FORMAT)
def setup_handler_logging_level(handler_type, level):
"""Setup of the handler for set the logging level
@ -103,17 +129,13 @@ def setup_logging(shell, cloud_config):
log_file = cloud_config.config.get('log_file', None)
if log_file:
# setup the logging context
log_cont = _LogContext(
clouds_name=cloud_config.config.get('cloud'),
project_name=cloud_config.auth.get('project_name'),
username=cloud_config.auth.get('username'),
)
formatter = _FileFormatter(config=cloud_config)
# setup the logging handler
log_handler = _setup_handler_for_logging(
logging.FileHandler,
log_level,
file_name=log_file,
context=log_cont,
formatter=formatter,
)
if log_level == logging.DEBUG:
# DEBUG only.
@ -123,7 +145,7 @@ def setup_logging(shell, cloud_config):
shell.operation_log.addHandler(log_handler)
def _setup_handler_for_logging(handler_type, level, file_name, context):
def _setup_handler_for_logging(handler_type, level, file_name, formatter):
"""Setup of the handler
Setup of the handler for addition of the logging handler,
@ -132,7 +154,7 @@ def _setup_handler_for_logging(handler_type, level, file_name, context):
:param handler_type: type of logging handler
:param level: logging level
:param file_name: name of log-file
:param context: instance of _LogContext()
:param formatter: instance of logging.Formatter
:return: logging handler
"""
@ -142,11 +164,6 @@ def _setup_handler_for_logging(handler_type, level, file_name, context):
handler = logging.FileHandler(
filename=file_name,
)
formatter = _LogContextFormatter(
context=context,
fmt=_LOG_MESSAGE_FORMAT,
datefmt=_LOG_DATE_FORMAT,
)
handler.setFormatter(formatter)
handler.setLevel(level)
@ -155,40 +172,3 @@ def _setup_handler_for_logging(handler_type, level, file_name, context):
root_logger.addHandler(handler)
return handler
class _LogContext(object):
"""Helper class to represent useful information about a logging context"""
def __init__(self, clouds_name=None, project_name=None, username=None):
"""Initialize _LogContext instance
:param clouds_name: one of the cloud name in configuration file
:param project_name: the project name in cloud(clouds_name)
:param username: the user name in cloud(clouds_name)
"""
self.clouds_name = clouds_name
self.project_name = project_name
self.username = username
def to_dict(self):
return {
'clouds_name': self.clouds_name,
'project_name': self.project_name,
'username': self.username
}
class _LogContextFormatter(logging.Formatter):
"""Customize the logging format for logging handler"""
def __init__(self, *args, **kwargs):
self.context = kwargs.pop('context', None)
logging.Formatter.__init__(self, *args, **kwargs)
def format(self, record):
d = self.context.to_dict()
for k, v in d.items():
setattr(record, k, v)
return logging.Formatter.format(self, record)

View File

@ -107,40 +107,28 @@ class TestContext(utils.TestCase):
simplefilter.assert_called_with("once")
class Test_LogContext(utils.TestCase):
def setUp(self):
super(Test_LogContext, self).setUp()
class TestFileFormatter(utils.TestCase):
def test_nothing(self):
formatter = context._FileFormatter()
self.assertEqual(('%(asctime)s.%(msecs)03d %(process)d %(levelname)s '
'%(name)s %(message)s'), formatter.fmt)
def test_context(self):
ctx = context._LogContext()
self.assertTrue(ctx)
def test_options(self):
class Opts(object):
cloud = 'cloudy'
os_project_name = 'projecty'
username = 'usernamey'
options = Opts()
formatter = context._FileFormatter(options=options)
self.assertEqual(('%(asctime)s.%(msecs)03d %(process)d %(levelname)s '
'%(name)s [cloudy usernamey projecty] %(message)s'),
formatter.fmt)
def test_context_to_dict(self):
ctx = context._LogContext('cloudsName', 'projectName', 'userNmae')
ctx_dict = ctx.to_dict()
self.assertEqual('cloudsName', ctx_dict['clouds_name'])
self.assertEqual('projectName', ctx_dict['project_name'])
self.assertEqual('userNmae', ctx_dict['username'])
class Test_LogContextFormatter(utils.TestCase):
def setUp(self):
super(Test_LogContextFormatter, self).setUp()
self.ctx = context._LogContext('cloudsName', 'projectName', 'userNmae')
self.addfmt = "%(clouds_name)s %(project_name)s %(username)s"
def test_contextrrormatter(self):
ctxfmt = context._LogContextFormatter()
self.assertTrue(ctxfmt)
def test_context_format(self):
record = mock.MagicMock()
logging.Formatter.format = mock.MagicMock()
logging.Formatter.format.return_value = record
ctxfmt = context._LogContextFormatter(context=self.ctx,
fmt=self.addfmt)
addctx = ctxfmt.format(record)
self.assertEqual('cloudsName', addctx.clouds_name)
self.assertEqual('projectName', addctx.project_name)
self.assertEqual('userNmae', addctx.username)
def test_config(self):
config = mock.Mock()
config.config = {'cloud': 'cloudy'}
config.auth = {'project_name': 'projecty', 'username': 'usernamey'}
formatter = context._FileFormatter(config=config)
self.assertEqual(('%(asctime)s.%(msecs)03d %(process)d %(levelname)s '
'%(name)s [cloudy usernamey projecty] %(message)s'),
formatter.fmt)