From 9e30c25e373cab38bd07c2a6817df07be137a5ce Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jason=20K=C3=B6lker?= Date: Mon, 13 Feb 2012 16:26:31 -0600 Subject: [PATCH] Allow file logging config * 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 --- nova/__init__.py | 7 +- nova/flags.py | 10 +- nova/log.py | 374 +++++++++++++++--------------------- nova/tests/test_log.py | 60 +++--- nova/tests/test_notifier.py | 2 +- nova/tests/test_volume.py | 17 +- nova/utils.py | 6 +- 7 files changed, 196 insertions(+), 280 deletions(-) diff --git a/nova/__init__.py b/nova/__init__.py index f2e9684d3..00ee99c37 100644 --- a/nova/__init__.py +++ b/nova/__init__.py @@ -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') diff --git a/nova/flags.py b/nova/flags.py index af490e287..8bec831c4 100644 --- a/nova/flags.py +++ b/nova/flags.py @@ -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'), diff --git a/nova/log.py b/nova/log.py index a9f7af70f..a99147a74 100644 --- a/nova/log.py +++ b/nova/log.py @@ -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): diff --git a/nova/tests/test_log.py b/nova/tests/test_log.py index 122351ff6..6a4e2b671 100644 --- a/nova/tests/test_log.py +++ b/nova/tests/test_log.py @@ -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()) diff --git a/nova/tests/test_notifier.py b/nova/tests/test_notifier.py index b13f203a4..be6c483e2 100644 --- a/nova/tests/test_notifier.py +++ b/nova/tests/test_notifier.py @@ -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): diff --git a/nova/tests/test_volume.py b/nova/tests/test_volume.py index 7d7ed614c..38768fb5e 100644 --- a/nova/tests/test_volume.py +++ b/nova/tests/test_volume.py @@ -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.""" diff --git a/nova/utils.py b/nova/utils.py index 0af09e809..96f0a57f0 100644 --- a/nova/utils.py +++ b/nova/utils.py @@ -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