openstack/nova
Code Issues Proposed changes

Allow file logging config

Browse Source 
* Fixes lp904305
* remove module level log functions (getLogger to rule them all)
* Move specific Environment logging to the one place it is used
* Wrap getLogger to return a logger wrapped in a NovaContextAdapter
* Do not overwrite the root logger
* save_and_reraise_exception logs via error for passing exc_info
* Uses CommonConfigOptions for compatability across Openstack Projects
* Prefers CommonConfigOptions over legacy options
* Install a NullHandler on the root logger if configured by FLAGS
* Include example logging config file to mimic Nova defaults

Change-Id: Ie59c3f755c142e2b7dc3b94b4e82e142e157bfac
This commit is contained in:
Jason Kölker 2012-02-13 16:26:31 -06:00
parent 6769652801
commit 2f317ba79f
9 changed files with 279 additions and 283 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

76
etc/nova/logging_sample.conf Normal file
View File

@ -0,0 +1,76 @@
[loggers]
keys = root, nova
[handlers]
keys = stderr, stdout, watchedfile, syslog, null
[formatters]
keys = legacynova, default
[logger_root]
level = WARNING
handlers = null
[logger_nova]
level = INFO
handlers = stderr
qualname = nova
[logger_amqplib]
level = WARNING
handlers = stderr
qualname = amqplib
[logger_sqlalchemy]
level = WARNING
handlers = stderr
qualname = sqlalchemy
# "level = INFO" logs SQL queries.
# "level = DEBUG" logs SQL queries and results.
# "level = WARNING" logs neither. (Recommended for production systems.)
[logger_boto]
level = WARNING
handlers = stderr
qualname = boto
[logger_suds]
level = INFO
handlers = stderr
qualname = suds
[logger_eventletwsgi]
level = WARNING
handlers = stderr
qualname = eventlet.wsgi.server
[handler_stderr]
class = StreamHandler
args = (sys.stderr,)
formatter = legacynova
[handler_stdout]
class = StreamHandler
args = (sys.stdout,)
formatter = legacynova
[handler_watchedfile]
class = handlers.WatchedFileHandler
args = ('nova.log',)
formatter = legacynova
[handler_syslog]
class = handlers.SysLogHandler
args = ('/dev/log', handlers.SysLogHandler.LOG_USER)
formatter = legacynova
[handler_null]
class = nova.log.NullHandler
formatter = default
args = ()
[formatter_legacynova]
class = nova.log.LegacyNovaFormatter
[formatter_default]
format = %(message)s

7
nova/__init__.py
View File

@ -32,6 +32,11 @@
"""
import gettext
import logging
gettext.install("nova", unicode=1)
gettext.install('nova', unicode=1)
# NOTE(jkoelker) This configures the root logger if it is not already
# configured so messages from logging setup can be written
# to the console
logging.basicConfig(format='%(message)s')

10
nova/api/ec2/__init__.py
View File

@ -627,9 +627,13 @@ class Executor(wsgi.Application):
context=context)
return ec2_error(req, request_id, type(ex).__name__, unicode(ex))
except Exception as ex:
extra = {'environment': req.environ}
LOG.exception(_('Unexpected error raised: %s'), unicode(ex),
extra=extra, context=context)
env = req.environ.copy()
for k in env.keys():
if not isinstance(env[k], basestring):
env.pop(k)
LOG.exception(_('Unexpected error raised: %s'), unicode(ex))
LOG.error(_('Environment: %s') % utils.dumps(env))
return ec2_error(req, request_id, 'UnknownError',
_('An unknown error has occurred. '
'Please try your request again.'))

10
nova/flags.py
View File

@ -34,7 +34,7 @@ from nova.compat import flagfile
from nova.openstack.common import cfg
class NovaConfigOpts(cfg.ConfigOpts):
class NovaConfigOpts(cfg.CommonConfigOpts):
def __init__(self, *args, **kwargs):
super(NovaConfigOpts, self).__init__(*args, **kwargs)
@ -66,23 +66,17 @@ def _get_my_ip():
(addr, port) = csock.getsockname()
csock.close()
return addr
except socket.error as ex:
except socket.error:
return "127.0.0.1"
log_opts = [
cfg.BoolOpt('verbose',
default=False,
help='show debug output'),
cfg.StrOpt('logdir',
default=None,
help='output to a per-service log file in named directory'),
cfg.StrOpt('logfile',
default=None,
help='output to named file'),
cfg.BoolOpt('use_syslog',
default=False,
help='output to syslog'),
cfg.BoolOpt('use_stderr',
default=True,
help='log to standard error'),

374
nova/log.py
View File

@ -31,8 +31,8 @@ It also allows setting of formatting information through flags.
import cStringIO
import inspect
import json
import logging
import logging.config
import logging.handlers
import os
import stat
@ -84,40 +84,25 @@ log_opts = [
FLAGS = flags.FLAGS
FLAGS.register_opts(log_opts)
# A list of things we want to replicate from logging.
# levels
CRITICAL = logging.CRITICAL
FATAL = logging.FATAL
ERROR = logging.ERROR
WARNING = logging.WARNING
WARN = logging.WARN
INFO = logging.INFO
DEBUG = logging.DEBUG
NOTSET = logging.NOTSET
# methods
getLogger = logging.getLogger
debug = logging.debug
info = logging.info
warning = logging.warning
warn = logging.warn
error = logging.error
exception = logging.exception
critical = logging.critical
log = logging.log
# handlers
StreamHandler = logging.StreamHandler
WatchedFileHandler = logging.handlers.WatchedFileHandler
# logging.SysLogHandler is nicer than logging.logging.handler.SysLogHandler.
SysLogHandler = logging.handlers.SysLogHandler
# our new audit level
AUDIT = logging.INFO + 1
logging.addLevelName(AUDIT, 'AUDIT')
# NOTE(jkoelker) Since we synthesized an audit level, make the logging
# module aware of it so it acts like other levels.
logging.AUDIT = logging.INFO + 1
logging.addLevelName(logging.AUDIT, 'AUDIT')
try:
NullHandler = logging.NullHandler
except AttributeError: # NOTE(jkoelker) NullHandler added in Python 2.7
class NullHandler(logging.Handler):
def handle(self, record):
pass
def emit(self, record):
pass
def createLock(self):
self.lock = None
def _dictify_context(context):
@ -133,134 +118,52 @@ def _get_binary_name():
def _get_log_file_path(binary=None):
if FLAGS.logfile:
return FLAGS.logfile
if FLAGS.logdir:
logfile = FLAGS.log_file or FLAGS.logfile
logdir = FLAGS.log_dir or FLAGS.logdir
if logfile and not logdir:
return logfile
if logfile and logdir:
return os.path.join(logdir, logfile)
if logdir:
binary = binary or _get_binary_name()
return '%s.log' % (os.path.join(FLAGS.logdir, binary),)
return '%s.log' % (os.path.join(logdir, binary),)
class NovaLogger(logging.Logger):
"""NovaLogger manages request context and formatting.
class NovaContextAdapter(logging.LoggerAdapter):
warn = logging.LoggerAdapter.warning
This becomes the class that is instantiated by logging.getLogger.
def __init__(self, logger):
self.logger = logger
"""
def audit(self, msg, *args, **kwargs):
self.log(logging.AUDIT, msg, *args, **kwargs)
def __init__(self, name, level=NOTSET):
logging.Logger.__init__(self, name, level)
self.setup_from_flags()
def process(self, msg, kwargs):
if 'extra' not in kwargs:
kwargs['extra'] = {}
extra = kwargs['extra']
def setup_from_flags(self):
"""Setup logger from flags."""
level = NOTSET
for pair in FLAGS.default_log_levels:
logger, _sep, level_name = pair.partition('=')
# NOTE(todd): if we set a.b, we want a.b.c to have the same level
# (but not a.bc, so we check the dot)
if self.name == logger or self.name.startswith("%s." % logger):
level = globals()[level_name]
self.setLevel(level)
def _update_extra(self, params):
if 'extra' not in params:
params['extra'] = {}
extra = params['extra']
context = None
if 'context' in params:
context = params['context']
del params['context']
context = kwargs.pop('context', None)
if not context:
context = getattr(local.store, 'context', None)
if context:
extra.update(_dictify_context(context))
if 'instance' in params:
extra.update({'instance': (FLAGS.instance_format
% params['instance'])})
del params['instance']
else:
extra.update({'instance': ''})
instance = kwargs.pop('instance', None)
instance_extra = ''
if instance:
instance_extra = FLAGS.instance_format % instance
extra.update({'instance': instance_extra})
extra.update({"nova_version": version.version_string_with_vcs()})
#NOTE(ameade): The following calls to _log must be maintained as direct
#calls. _log introspects the call stack to get information such as the
#filename and line number the logging method was called from.
def log(self, lvl, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(lvl):
self._log(lvl, msg, args, **kwargs)
def debug(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(DEBUG):
self._log(DEBUG, msg, args, **kwargs)
def info(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(INFO):
self._log(INFO, msg, args, **kwargs)
def warn(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(WARN):
self._log(WARN, msg, args, **kwargs)
def warning(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(WARNING):
self._log(WARNING, msg, args, **kwargs)
def error(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(ERROR):
self._log(ERROR, msg, args, **kwargs)
def critical(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(CRITICAL):
self._log(CRITICAL, msg, args, **kwargs)
def fatal(self, msg, *args, **kwargs):
self._update_extra(kwargs)
if self.isEnabledFor(FATAL):
self._log(FATAL, msg, args, **kwargs)
def audit(self, msg, *args, **kwargs):
"""Shortcut for our AUDIT level."""
self._update_extra(kwargs)
if self.isEnabledFor(AUDIT):
self._log(AUDIT, msg, args, **kwargs)
def addHandler(self, handler):
"""Each handler gets our custom formatter."""
handler.setFormatter(_formatter)
return logging.Logger.addHandler(self, handler)
def exception(self, msg, *args, **kwargs):
"""Logging.exception doesn't handle kwargs, so breaks context."""
if not kwargs.get('exc_info'):
kwargs['exc_info'] = 1
self.error(msg, *args, **kwargs)
# NOTE(todd): does this really go here, or in _log ?
extra = kwargs.get('extra')
if not extra:
return
env = extra.get('environment')
if env:
env = env.copy()
for k in env.keys():
if not isinstance(env[k], str):
env.pop(k)
message = 'Environment: %s' % json.dumps(env)
kwargs.pop('exc_info')
self.error(message, **kwargs)
return msg, kwargs
class NovaFormatter(logging.Formatter):
class LegacyNovaFormatter(logging.Formatter):
"""A nova.context.RequestContext aware formatter configured through flags.
The flags used to set format strings are: logging_context_format_string
@ -275,6 +178,9 @@ class NovaFormatter(logging.Formatter):
def format(self, record):
"""Uses contextstring if request_id is set, otherwise default."""
if 'instance' not in record.__dict__:
record.__dict__['instance'] = ''
if record.__dict__.get('request_id', None):
self._fmt = FLAGS.logging_context_format_string
else:
@ -306,54 +212,6 @@ class NovaFormatter(logging.Formatter):
return '\n'.join(formatted_lines)
_formatter = NovaFormatter()
class NovaRootLogger(NovaLogger):
def __init__(self, name, level=NOTSET):
self.logpath = None
self.filelog = None
self.streamlog = None
self.syslog = None
NovaLogger.__init__(self, name, level)
def setup_from_flags(self):
"""Setup logger from flags."""
global _filelog
if self.syslog:
self.removeHandler(self.syslog)
self.syslog = None
if FLAGS.use_syslog:
self.syslog = SysLogHandler(address='/dev/log')
self.addHandler(self.syslog)
logpath = _get_log_file_path()
if logpath:
if logpath != self.logpath:
self.removeHandler(self.filelog)
self.filelog = WatchedFileHandler(logpath)
self.addHandler(self.filelog)
self.logpath = logpath
mode = int(FLAGS.logfile_mode, 8)
st = os.stat(self.logpath)
if st.st_mode != (stat.S_IFREG | mode):
os.chmod(self.logpath, mode)
else:
self.removeHandler(self.filelog)
if self.streamlog:
self.removeHandler(self.streamlog)
self.streamlog = None
if FLAGS.use_stderr:
self.streamlog = StreamHandler()
self.addHandler(self.streamlog)
if FLAGS.publish_errors:
self.addHandler(PublishErrorsHandler(ERROR))
if FLAGS.verbose:
self.setLevel(DEBUG)
else:
self.setLevel(INFO)
class PublishErrorsHandler(logging.Handler):
def emit(self, record):
nova.notifier.api.notify('nova.error.publisher', 'error_notification',
@ -364,42 +222,116 @@ def handle_exception(type, value, tb):
extra = {}
if FLAGS.verbose:
extra['exc_info'] = (type, value, tb)
logging.root.critical(str(value), **extra)
def reset():
"""Resets logging handlers. Should be called if FLAGS changes."""
for logger in NovaLogger.manager.loggerDict.itervalues():
if isinstance(logger, NovaLogger):
logger.setup_from_flags()
getLogger().critical(str(value), **extra)
def setup():
"""Setup nova logging."""
if not isinstance(logging.root, NovaRootLogger):
logging._acquireLock()
for handler in logging.root.handlers:
logging.root.removeHandler(handler)
logging.root = NovaRootLogger("nova")
NovaLogger.root = logging.root
NovaLogger.manager.root = logging.root
for logger in NovaLogger.manager.loggerDict.itervalues():
logger.root = logging.root
if isinstance(logger, logging.Logger):
NovaLogger.manager._fixupParents(logger)
NovaLogger.manager.loggerDict["nova"] = logging.root
logging._releaseLock()
sys.excepthook = handle_exception
reset()
sys.excepthook = handle_exception
if FLAGS.log_config:
try:
logging.config.fileConfig(FLAGS.log_config)
except Exception:
traceback.print_exc()
raise
else:
_setup_logging_from_flags()
root = logging.root
logging.setLoggerClass(NovaLogger)
def _find_facility_from_flags():
facility_names = logging.handlers.SysLogHandler.facility_names
facility = getattr(logging.handlers.SysLogHandler,
FLAGS.syslog_log_facility,
None)
if facility is None and FLAGS.syslog_log_facility in facility_names:
facility = facility_names.get(FLAGS.syslog_log_facility)
if facility is None:
valid_facilities = facility_names.keys()
consts = ['LOG_AUTH', 'LOG_AUTHPRIV', 'LOG_CRON', 'LOG_DAEMON',
'LOG_FTP', 'LOG_KERN', 'LOG_LPR', 'LOG_MAIL', 'LOG_NEWS',
'LOG_AUTH', 'LOG_SYSLOG', 'LOG_USER', 'LOG_UUCP',
'LOG_LOCAL0', 'LOG_LOCAL1', 'LOG_LOCAL2', 'LOG_LOCAL3',
'LOG_LOCAL4', 'LOG_LOCAL5', 'LOG_LOCAL6', 'LOG_LOCAL7']
valid_facilities.extend(consts)
raise TypeError(_('syslog facility must be one of: %s') %
', '.join("'%s'" % fac
for fac in valid_facilities))
return facility
def audit(msg, *args, **kwargs):
"""Shortcut for logging to root log with severity 'AUDIT'."""
logging.root.audit(msg, *args, **kwargs)
def _setup_logging_from_flags():
nova_root = getLogger().logger
for handler in nova_root.handlers:
nova_root.removeHandler(handler)
if FLAGS.use_syslog:
facility = _find_facility_from_flags()
syslog = logging.handlers.SysLogHandler(address='/dev/log',
facility=facility)
nova_root.addHandler(syslog)
logpath = _get_log_file_path()
if logpath:
filelog = logging.handlers.WatchedFileHandler(logpath)
nova_root.addHandler(filelog)
mode = int(FLAGS.logfile_mode, 8)
st = os.stat(logpath)
if st.st_mode != (stat.S_IFREG | mode):
os.chmod(logpath, mode)
if FLAGS.use_stderr:
streamlog = logging.StreamHandler()
nova_root.addHandler(streamlog)
elif not FLAGS.log_file:
streamlog = logging.StreamHandler(stream=sys.stdout)
nova_root.addHandler(streamlog)
if FLAGS.publish_errors:
nova_root.addHandler(PublishErrorsHandler(logging.ERROR))
for handler in nova_root.handlers:
datefmt = FLAGS.log_date_format
if FLAGS.log_format:
handler.setFormatter(logging.Formatter(fmt=FLAGS.log_format,
datefmt=datefmt))
handler.setFormatter(LegacyNovaFormatter(datefmt=datefmt))
if FLAGS.verbose or FLAGS.debug:
nova_root.setLevel(logging.DEBUG)
else:
nova_root.setLevel(logging.INFO)
level = logging.NOTSET
for pair in FLAGS.default_log_levels:
mod, _sep, level_name = pair.partition('=')
level = logging.getLevelName(level_name)
logger = logging.getLogger(mod)
logger.setLevel(level)
# NOTE(jkoelker) Clear the handlers for the root logger that was setup
# by basicConfig in nova/__init__.py and install the
# NullHandler.
root = logging.getLogger()
for handler in root.handlers:
root.removeHandler(handler)
handler = NullHandler()
handler.setFormatter(logging.Formatter())
root.addHandler(handler)
_loggers = {}
def getLogger(name='nova'):
if name not in _loggers:
_loggers[name] = NovaContextAdapter(logging.getLogger(name))
return _loggers[name]
class WritableLogger(object):

60
nova/tests/test_log.py
View File

@ -1,4 +1,5 @@
import cStringIO
import logging
from nova import context
from nova import flags
@ -12,47 +13,42 @@ def _fake_context():
return context.RequestContext(1, 1)
class RootLoggerTestCase(test.TestCase):
class LoggerTestCase(test.TestCase):
def setUp(self):
super(RootLoggerTestCase, self).setUp()
self.log = log.logging.root
def test_is_nova_instance(self):
self.assert_(isinstance(self.log, log.NovaLogger))
def test_name_is_nova(self):
self.assertEqual("nova", self.log.name)
super(LoggerTestCase, self).setUp()
self.log = log.getLogger()
def test_handlers_have_nova_formatter(self):
formatters = []
for h in self.log.handlers:
for h in self.log.logger.handlers:
f = h.formatter
if isinstance(f, log.NovaFormatter):
if isinstance(f, log.LegacyNovaFormatter):
formatters.append(f)
self.assert_(formatters)
self.assertEqual(len(formatters), len(self.log.handlers))
self.assertEqual(len(formatters), len(self.log.logger.handlers))
def test_handles_context_kwarg(self):
self.log.info("foo", context=_fake_context())
self.assert_(True) # didn't raise exception
def test_module_level_methods_handle_context_arg(self):
log.info("foo", context=_fake_context())
self.assert_(True) # didn't raise exception
def test_module_level_audit_handles_context_arg(self):
log.audit("foo", context=_fake_context())
def test_audit_handles_context_arg(self):
self.log.audit("foo", context=_fake_context())
self.assert_(True) # didn't raise exception
def test_will_be_verbose_if_verbose_flag_set(self):
self.flags(verbose=True)
log.reset()
self.assertEqual(log.DEBUG, self.log.level)
log.setup()
self.assertEqual(logging.DEBUG, self.log.logger.getEffectiveLevel())
def test_will_not_be_verbose_if_verbose_flag_not_set(self):
self.flags(verbose=False)
log.reset()
self.assertEqual(log.INFO, self.log.level)
log.setup()
self.assertEqual(logging.INFO, self.log.logger.getEffectiveLevel())
def test_no_logging_via_module(self):
for func in ('critical', 'error', 'exception', 'warning', 'warn',
'info', 'debug', 'log', 'audit'):
self.assertRaises(AttributeError, getattr, log, func)
class LogHandlerTestCase(test.TestCase):
@ -84,16 +80,17 @@ class NovaFormatterTestCase(test.TestCase):
"[%(request_id)s]: %(message)s",
logging_default_format_string="NOCTXT: %(message)s",
logging_debug_format_suffix="--DBG")
self.log = log.logging.root
self.log = log.getLogger()
self.stream = cStringIO.StringIO()
self.handler = log.StreamHandler(self.stream)
self.log.addHandler(self.handler)
self.level = self.log.level
self.log.setLevel(log.DEBUG)
self.handler = logging.StreamHandler(self.stream)
self.handler.setFormatter(log.LegacyNovaFormatter())
self.log.logger.addHandler(self.handler)
self.level = self.log.logger.getEffectiveLevel()
self.log.logger.setLevel(logging.DEBUG)
def tearDown(self):
self.log.setLevel(self.level)
self.log.removeHandler(self.handler)
self.log.logger.setLevel(self.level)
self.log.logger.removeHandler(self.handler)
super(NovaFormatterTestCase, self).tearDown()
def test_uncontextualized_log(self):
@ -118,11 +115,12 @@ class NovaLoggerTestCase(test.TestCase):
levels.append("nova-test=AUDIT")
self.flags(default_log_levels=levels,
verbose=True)
log.setup()
self.log = log.getLogger('nova-test')
def test_has_level_from_flags(self):
self.assertEqual(log.AUDIT, self.log.level)
self.assertEqual(logging.AUDIT, self.log.logger.getEffectiveLevel())
def test_child_log_has_level_of_parent_flag(self):
l = log.getLogger('nova-test.foo')
self.assertEqual(log.AUDIT, l.level)
self.assertEqual(logging.AUDIT, l.logger.getEffectiveLevel())

2
nova/tests/test_notifier.py
View File

@ -105,7 +105,7 @@ class NotifierTestCase(test.TestCase):
'nova.notifier.rabbit_notifier')
self.stubs.Set(nova.flags.FLAGS, 'publish_errors', True)
LOG = log.getLogger('nova')
LOG.setup_from_flags()
log.setup()
msgs = []
def mock_notify(context, topic, data):

17
nova/tests/test_volume.py
View File

@ -280,14 +280,11 @@ class DriverTestCase(test.TestCase):
log = logging.getLogger()
self.stream = cStringIO.StringIO()
log.addHandler(logging.StreamHandler(self.stream))
log.logger.addHandler(logging.logging.StreamHandler(self.stream))
inst = {}
self.instance_id = db.instance_create(self.context, inst)['id']
def tearDown(self):
super(DriverTestCase, self).tearDown()
def _attach_volume(self):
"""Attach volumes to an instance. This function also sets
a fake log message."""
@ -304,12 +301,6 @@ class VolumeDriverTestCase(DriverTestCase):
"""Test case for VolumeDriver"""
driver_name = "nova.volume.driver.VolumeDriver"
def setUp(self):
super(VolumeDriverTestCase, self).setUp()
def tearDown(self):
super(VolumeDriverTestCase, self).tearDown()
def test_delete_busy_volume(self):
"""Test deleting a busy volume."""
self.stubs.Set(self.volume.driver, '_volume_not_present',
@ -332,12 +323,6 @@ class ISCSITestCase(DriverTestCase):
"""Test Case for ISCSIDriver"""
driver_name = "nova.volume.driver.ISCSIDriver"
def setUp(self):
super(ISCSITestCase, self).setUp()
def tearDown(self):
super(ISCSITestCase, self).tearDown()
def _attach_volume(self):
"""Attach volumes to an instance. This function also sets
a fake log message."""

6
nova/utils.py
View File

@ -1118,8 +1118,10 @@ def save_and_reraise_exception():
try:
yield
except Exception:
LOG.exception(_('Original exception being dropped'),
exc_info=(type_, value, traceback))
# NOTE(jkoelker): Using LOG.error here since it accepts exc_info
# as a kwargs.
LOG.error(_('Original exception being dropped'),
exc_info=(type_, value, traceback))
raise
raise type_, value, traceback