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

@@ -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')

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'),

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
+# NOTE(jkoelker) Since we synthesized an audit level, make the logging
-logging.addLevelName(AUDIT, 'AUDIT')
+#                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:
+    logfile = FLAGS.log_file or FLAGS.logfile
-        return FLAGS.logfile
+    logdir = FLAGS.log_dir or FLAGS.logdir
-    if 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):
+class NovaContextAdapter(logging.LoggerAdapter):
-    """NovaLogger manages request context and formatting.
+    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):
+    def process(self, msg, kwargs):
-        logging.Logger.__init__(self, name, level)
+        if 'extra' not in kwargs:
-        self.setup_from_flags()
+            kwargs['extra'] = {}
+        extra = kwargs['extra']
 
-    def setup_from_flags(self):
+        context = kwargs.pop('context', None)
-        """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']
         if not context:
             context = getattr(local.store, 'context', None)
         if context:
             extra.update(_dictify_context(context))
 
-        if 'instance' in params:
+        instance = kwargs.pop('instance', None)
-            extra.update({'instance': (FLAGS.instance_format
+        instance_extra = ''
-                                       % params['instance'])})
+        if instance:
-            del params['instance']
+            instance_extra = FLAGS.instance_format % instance
-        else:
+        extra.update({'instance': instance_extra})
-            extra.update({'instance': ''})
 
         extra.update({"nova_version": version.version_string_with_vcs()})
 
-    #NOTE(ameade): The following calls to _log must be maintained as direct
+        return msg, kwargs
-    #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)
 
 
-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)
+    getLogger().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()
 
 
 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()
+
+    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
+def _find_facility_from_flags():
-logging.setLoggerClass(NovaLogger)
+    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):
+def _setup_logging_from_flags():
-    """Shortcut for logging to root log with severity 'AUDIT'."""
+    nova_root = getLogger().logger
-    logging.root.audit(msg, *args, **kwargs)
+    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):

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()
+        super(LoggerTestCase, self).setUp()
-        self.log = log.logging.root
+        self.log = log.getLogger()
-
-    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)
 
     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):
+    def test_audit_handles_context_arg(self):
-        log.info("foo", context=_fake_context())
+        self.log.audit("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())
         self.assert_(True)  # didn't raise exception
 
     def test_will_be_verbose_if_verbose_flag_set(self):
         self.flags(verbose=True)
-        log.reset()
+        log.setup()
-        self.assertEqual(log.DEBUG, self.log.level)
+        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()
+        log.setup()
-        self.assertEqual(log.INFO, self.log.level)
+        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.handler = logging.StreamHandler(self.stream)
-        self.log.addHandler(self.handler)
+        self.handler.setFormatter(log.LegacyNovaFormatter())
-        self.level = self.log.level
+        self.log.logger.addHandler(self.handler)
-        self.log.setLevel(log.DEBUG)
+        self.level = self.log.logger.getEffectiveLevel()
+        self.log.logger.setLevel(logging.DEBUG)
 
     def tearDown(self):
-        self.log.setLevel(self.level)
+        self.log.logger.setLevel(self.level)
-        self.log.removeHandler(self.handler)
+        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())

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):

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."""

nova/utils.py

@@ -1118,7 +1118,9 @@ def save_and_reraise_exception():
     try:
         yield
     except Exception:
-        LOG.exception(_('Original exception being dropped'),
+        # 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