Fixes various issues regarding verbose logging and logging errors on import.

* Adds a call to logging.reset() after flags are loaded via FLAGS()
* Uses logfile flag to log properly during run_tests
* Only adds handlers to root logger
* Removes the stream handler if logfile is set
* Syslog handler is in addition to logfile or stream handler
* Removed need for logging.basicConfig()

bin/nova-ajax-console-proxy

@@ -25,7 +25,6 @@ from eventlet.green import urllib2
 
 import exceptions
 import gettext
-import logging
 import os
 import sys
 import time
@@ -130,6 +129,7 @@ class AjaxConsoleProxy(object):
 if __name__ == '__main__':
     utils.default_flagfile()
     FLAGS(sys.argv)
+    logging.setup()
     server = wsgi.Server()
     acp = AjaxConsoleProxy()
     acp.register_listeners()

bin/nova-api

@@ -39,9 +39,7 @@ from nova import log as logging
 from nova import version
 from nova import wsgi
 
-logging.basicConfig()
 LOG = logging.getLogger('nova.api')
-LOG.setLevel(logging.DEBUG)
 
 FLAGS = flags.FLAGS
 
@@ -71,7 +69,8 @@ def run_app(paste_config_file):
         return
 
     # NOTE(todd): redo logging config, verbose could be set in paste config
-    logging.basicConfig()
+    logging.reset()
+
     server = wsgi.Server()
     for app in apps:
         server.start(*app)
@@ -80,6 +79,7 @@ def run_app(paste_config_file):
 
 if __name__ == '__main__':
     FLAGS(sys.argv)
+    logging.setup()
     LOG.audit(_("Starting nova-api node (version %s)"),
               version.version_string_with_vcs())
     conf = wsgi.paste_config_file('nova-api.conf')

bin/nova-combined

@@ -49,7 +49,7 @@ FLAGS = flags.FLAGS
 if __name__ == '__main__':
     utils.default_flagfile()
     FLAGS(sys.argv)
-    logging.basicConfig()
+    logging.setup()
 
     compute = service.Service.create(binary='nova-compute')
     network = service.Service.create(binary='nova-network')
@@ -73,7 +73,6 @@ if __name__ == '__main__':
         apps.append((app, getattr(FLAGS, "%s_port" % api),
                      getattr(FLAGS, "%s_host" % api)))
     if len(apps) > 0:
-        logging.basicConfig()
         server = wsgi.Server()
         for app in apps:
             server.start(*app)

bin/nova-compute

@@ -36,10 +36,14 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 
 gettext.install('nova', unicode=1)
 
+from nova import flags
+from nova import log as logging
 from nova import service
 from nova import utils
 
 if __name__ == '__main__':
     utils.default_flagfile()
+    flags.FLAGS(sys.argv)
+    logging.setup()
     service.serve()
     service.wait()

bin/nova-console

@@ -35,10 +35,14 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 
 gettext.install('nova', unicode=1)
 
+from nova import flags
+from nova import log as logging
 from nova import service
 from nova import utils
 
 if __name__ == '__main__':
     utils.default_flagfile()
+    flags.FLAGS(sys.argv)
+    logging.setup()
     service.serve()
     service.wait()

bin/nova-dhcpbridge

@@ -102,7 +102,7 @@ def main():
     flagfile = os.environ.get('FLAGFILE', FLAGS.dhcpbridge_flagfile)
     utils.default_flagfile(flagfile)
     argv = FLAGS(sys.argv)
-    logging.basicConfig()
+    logging.setup()
     interface = os.environ.get('DNSMASQ_INTERFACE', 'br0')
     if int(os.environ.get('TESTING', '0')):
         FLAGS.fake_rabbit = True

bin/nova-direct-api

@@ -35,6 +35,7 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 gettext.install('nova', unicode=1)
 
 from nova import flags
+from nova import log as logging
 from nova import utils
 from nova import wsgi
 from nova.api import direct
@@ -48,6 +49,7 @@ flags.DEFINE_string('direct_host', '0.0.0.0', 'Direct API host')
 if __name__ == '__main__':
     utils.default_flagfile()
     FLAGS(sys.argv)
+    logging.setup()
 
     direct.register_service('compute', compute_api.API())
     direct.register_service('reflect', direct.Reflection())

bin/nova-import-canonical-imagestore

@@ -41,6 +41,7 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 gettext.install('nova', unicode=1)
 
 from nova import flags
+from nova import log as logging
 from nova import utils
 from nova.objectstore import image
 
@@ -92,6 +93,7 @@ def main():
     """Main entry point."""
     utils.default_flagfile()
     argv = FLAGS(sys.argv)
+    logging.setup()
     images = get_images()
 
     if len(argv) == 2:

bin/nova-instancemonitor

@@ -41,9 +41,6 @@ from nova import utils
 from nova import twistd
 from nova.compute import monitor
 
-# TODO(todd): shouldn't this be done with flags?  And what about verbose?
-logging.getLogger('boto').setLevel(logging.WARN)
-
 LOG = logging.getLogger('nova.instancemonitor')
 
 

bin/nova-manage

@@ -86,8 +86,6 @@ from nova.auth import manager
 from nova.cloudpipe import pipelib
 from nova.db import migration
 
-
-logging.basicConfig()
 FLAGS = flags.FLAGS
 flags.DECLARE('fixed_range', 'nova.network.manager')
 flags.DECLARE('num_networks', 'nova.network.manager')
@@ -710,6 +708,7 @@ def main():
     """Parse options and call the appropriate class/method."""
     utils.default_flagfile()
     argv = FLAGS(sys.argv)
+    logging.setup()
 
     script_name = argv.pop(0)
     if len(argv) < 1:

bin/nova-network

@@ -36,10 +36,14 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 
 gettext.install('nova', unicode=1)
 
+from nova import flags
+from nova import log as logging
 from nova import service
 from nova import utils
 
 if __name__ == '__main__':
     utils.default_flagfile()
+    flags.FLAGS(sys.argv)
+    logging.setup()
     service.serve()
     service.wait()

bin/nova-scheduler

@@ -36,10 +36,14 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 
 gettext.install('nova', unicode=1)
 
+from nova import flags
+from nova import log as logging
 from nova import service
 from nova import utils
 
 if __name__ == '__main__':
     utils.default_flagfile()
+    flags.FLAGS(sys.argv)
+    logging.setup()
     service.serve()
     service.wait()

bin/nova-volume

@@ -36,10 +36,14 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')):
 
 gettext.install('nova', unicode=1)
 
+from nova import flags
+from nova import log as logging
 from nova import service
 from nova import utils
 
 if __name__ == '__main__':
     utils.default_flagfile()
+    flags.FLAGS(sys.argv)
+    logging.setup()
     service.serve()
     service.wait()

nova/log.py

@@ -65,6 +65,7 @@ flags.DEFINE_string('logging_exception_prefix',
 flags.DEFINE_list('default_log_levels',
                   ['amqplib=WARN',
                    'sqlalchemy=WARN',
+                   'boto=WARN',
                    'eventlet.wsgi.server=WARN'],
                   'list of logger=LEVEL pairs')
 
@@ -117,7 +118,7 @@ def _get_binary_name():
     return os.path.basename(inspect.stack()[-1][1])
 
 
-def get_log_file_path(binary=None):
+def _get_log_file_path(binary=None):
     if FLAGS.logfile:
         return FLAGS.logfile
     if FLAGS.logdir:
@@ -125,25 +126,6 @@ def get_log_file_path(binary=None):
         return '%s.log' % (os.path.join(FLAGS.logdir, binary),)
 
 
-def basicConfig():
-    logging.basicConfig()
-    for handler in logging.root.handlers:
-        handler.setFormatter(_formatter)
-    if FLAGS.verbose:
-        logging.root.setLevel(logging.DEBUG)
-    else:
-        logging.root.setLevel(logging.INFO)
-    if FLAGS.use_syslog:
-        syslog = SysLogHandler(address='/dev/log')
-        syslog.setFormatter(_formatter)
-        logging.root.addHandler(syslog)
-    logpath = get_log_file_path()
-    if logpath:
-        logfile = WatchedFileHandler(logpath)
-        logfile.setFormatter(_formatter)
-        logging.root.addHandler(logfile)
-
-
 class NovaLogger(logging.Logger):
     """
     NovaLogger manages request context and formatting.
@@ -151,23 +133,19 @@ class NovaLogger(logging.Logger):
     This becomes the class that is instanciated by logging.getLogger.
     """
     def __init__(self, name, level=NOTSET):
-        level_name = self._get_level_from_flags(name, FLAGS)
-        level = globals()[level_name]
         logging.Logger.__init__(self, name, level)
+        self.setup_from_flags()
 
-    def _get_level_from_flags(self, name, FLAGS):
-        # if exactly "nova", or a child logger, honor the verbose flag
-        if (name == "nova" or name.startswith("nova.")) and FLAGS.verbose:
-            return 'DEBUG'
+    def setup_from_flags(self):
+        """Setup logger from flags"""
+        level = NOTSET
         for pair in FLAGS.default_log_levels:
-            logger, _sep, level = pair.partition('=')
+            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 name == logger:
-                return level
-            if name.startswith(logger) and name[len(logger)] == '.':
-                return level
-        return 'INFO'
+            if self.name == logger or self.name.startswith("%s." % logger):
+                level = globals()[level_name]
+        self.setLevel(level)
 
     def _log(self, level, msg, args, exc_info=None, extra=None, context=None):
         """Extract context from any log call"""
@@ -176,12 +154,12 @@ class NovaLogger(logging.Logger):
         if context:
             extra.update(_dictify_context(context))
         extra.update({"nova_version": version.version_string_with_vcs()})
-        logging.Logger._log(self, level, msg, args, exc_info, extra)
+        return logging.Logger._log(self, level, msg, args, exc_info, extra)
 
     def addHandler(self, handler):
         """Each handler gets our custom formatter"""
         handler.setFormatter(_formatter)
-        logging.Logger.addHandler(self, handler)
+        return logging.Logger.addHandler(self, handler)
 
     def audit(self, msg, *args, **kwargs):
         """Shortcut for our AUDIT level"""
@@ -208,23 +186,6 @@ class NovaLogger(logging.Logger):
             self.error(message, **kwargs)
 
 
-def handle_exception(type, value, tb):
-    logging.root.critical(str(value), exc_info=(type, value, tb))
-
-
-sys.excepthook = handle_exception
-logging.setLoggerClass(NovaLogger)
-
-
-class NovaRootLogger(NovaLogger):
-    pass
-
-if not isinstance(logging.root, NovaRootLogger):
-    logging.root = NovaRootLogger("nova.root", WARNING)
-    NovaLogger.root = logging.root
-    NovaLogger.manager.root = logging.root
-
-
 class NovaFormatter(logging.Formatter):
     """
     A nova.context.RequestContext aware formatter configured through flags.
@@ -271,8 +232,72 @@ class NovaFormatter(logging.Formatter):
 _formatter = NovaFormatter()
 
 
+class NovaRootLogger(NovaLogger):
+    def __init__(self, name, level=NOTSET):
+        self.logpath = None
+        self.filelog = None
+        self.syslog = SysLogHandler(address='/dev/log')
+        self.streamlog = StreamHandler()
+        NovaLogger.__init__(self, name, level)
+
+    def setup_from_flags(self):
+        """Setup logger from flags"""
+        global _filelog
+        if FLAGS.use_syslog:
+            self.addHandler(self.syslog)
+        else:
+            self.removeHandler(self.syslog)
+        logpath = _get_log_file_path()
+        if logpath:
+            self.removeHandler(self.streamlog)
+            if logpath != self.logpath:
+                self.removeHandler(self.filelog)
+                self.filelog = WatchedFileHandler(logpath)
+                self.addHandler(self.filelog)
+                self.logpath = logpath
+        else:
+            self.removeHandler(self.filelog)
+            self.addHandler(self.streamlog)
+        if FLAGS.verbose:
+            self.setLevel(DEBUG)
+        else:
+            self.setLevel(INFO)
+
+
+def handle_exception(type, value, tb):
+    logging.root.critical(str(value), exc_info=(type, value, tb))
+
+
+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()
+
+
+root = logging.root
+logging.setLoggerClass(NovaLogger)
+
+
 def audit(msg, *args, **kwargs):
     """Shortcut for logging to root log with sevrity 'AUDIT'."""
-    if len(logging.root.handlers) == 0:
-        basicConfig()
     logging.root.log(AUDIT, msg, *args, **kwargs)

nova/service.py

@@ -221,9 +221,6 @@ class Service(object):
 
 
 def serve(*services):
-    FLAGS(sys.argv)
-    logging.basicConfig()
-
     if not services:
         services = [Service.create()]
 

nova/test.py

@@ -33,10 +33,10 @@ from nova import context
 from nova import db
 from nova import fakerabbit
 from nova import flags
+from nova import log as logging
 from nova import rpc
 from nova import service
 from nova.network import manager as network_manager
-from nova.tests import fake_flags
 
 
 FLAGS = flags.FLAGS

nova/tests/fake_flags.py

@@ -41,3 +41,4 @@ FLAGS.iscsi_num_targets = 8
 FLAGS.verbose = True
 FLAGS.sql_connection = 'sqlite:///nova.sqlite'
 FLAGS.use_ipv6 = True
+FLAGS.logfile = 'tests.log'

nova/tests/test_auth.py

@@ -327,15 +327,6 @@ class AuthManagerTestCase(object):
 class AuthManagerLdapTestCase(AuthManagerTestCase, test.TestCase):
     auth_driver = 'nova.auth.ldapdriver.FakeLdapDriver'
 
-    def __init__(self, *args, **kwargs):
-        AuthManagerTestCase.__init__(self)
-        test.TestCase.__init__(self, *args, **kwargs)
-        import nova.auth.fakeldap as fakeldap
-        if FLAGS.flush_db:
-            LOG.info("Flushing datastore")
-            r = fakeldap.Store.instance()
-            r.flushdb()
-
 
 class AuthManagerDbTestCase(AuthManagerTestCase, test.TestCase):
     auth_driver = 'nova.auth.dbdriver.DbDriver'

nova/tests/test_console.py

@@ -21,7 +21,6 @@ Tests For Console proxy.
 """
 
 import datetime
-import logging
 
 from nova import context
 from nova import db
@@ -38,7 +37,6 @@ FLAGS = flags.FLAGS
 class ConsoleTestCase(test.TestCase):
     """Test case for console proxy"""
     def setUp(self):
-        logging.getLogger().setLevel(logging.DEBUG)
         super(ConsoleTestCase, self).setUp()
         self.flags(console_driver='nova.console.fake.FakeConsoleProxy',
                    stub_compute=True)

nova/tests/test_direct.py

@@ -19,7 +19,6 @@
 """Tests for Direct API."""
 
 import json
-import logging
 
 import webob
 

nova/tests/test_localization.py

@@ -15,7 +15,6 @@
 #    under the License.
 
 import glob
-import logging
 import os
 import re
 import sys

nova/tests/test_log.py

@@ -1,9 +1,12 @@
 import cStringIO
 
 from nova import context
+from nova import flags
 from nova import log
 from nova import test
 
+FLAGS = flags.FLAGS
+
 
 def _fake_context():
     return context.RequestContext(1, 1)
@@ -14,15 +17,11 @@ class RootLoggerTestCase(test.TestCase):
         super(RootLoggerTestCase, self).setUp()
         self.log = log.logging.root
 
-    def tearDown(self):
-        super(RootLoggerTestCase, self).tearDown()
-        log.NovaLogger.manager.loggerDict = {}
-
     def test_is_nova_instance(self):
         self.assert_(isinstance(self.log, log.NovaLogger))
 
-    def test_name_is_nova_root(self):
-        self.assertEqual("nova.root", self.log.name)
+    def test_name_is_nova(self):
+        self.assertEqual("nova", self.log.name)
 
     def test_handlers_have_nova_formatter(self):
         formatters = []
@@ -45,25 +44,36 @@ class RootLoggerTestCase(test.TestCase):
         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)
+
+    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)
+
 
 class LogHandlerTestCase(test.TestCase):
     def test_log_path_logdir(self):
-        self.flags(logdir='/some/path')
-        self.assertEquals(log.get_log_file_path(binary='foo-bar'),
+        self.flags(logdir='/some/path', logfile=None)
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
                          '/some/path/foo-bar.log')
 
     def test_log_path_logfile(self):
         self.flags(logfile='/some/path/foo-bar.log')
-        self.assertEquals(log.get_log_file_path(binary='foo-bar'),
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
                          '/some/path/foo-bar.log')
 
     def test_log_path_none(self):
-        self.assertTrue(log.get_log_file_path(binary='foo-bar') is None)
+        self.flags(logdir=None, logfile=None)
+        self.assertTrue(log._get_log_file_path(binary='foo-bar') is None)
 
     def test_log_path_logfile_overrides_logdir(self):
         self.flags(logdir='/some/other/path',
                    logfile='/some/path/foo-bar.log')
-        self.assertEquals(log.get_log_file_path(binary='foo-bar'),
+        self.assertEquals(log._get_log_file_path(binary='foo-bar'),
                          '/some/path/foo-bar.log')
 
 
@@ -76,13 +86,15 @@ class NovaFormatterTestCase(test.TestCase):
                    logging_debug_format_suffix="--DBG")
         self.log = log.logging.root
         self.stream = cStringIO.StringIO()
-        handler = log.StreamHandler(self.stream)
-        self.log.addHandler(handler)
+        self.handler = log.StreamHandler(self.stream)
+        self.log.addHandler(self.handler)
+        self.level = self.log.level
         self.log.setLevel(log.DEBUG)
 
     def tearDown(self):
+        self.log.setLevel(self.level)
+        self.log.removeHandler(self.handler)
         super(NovaFormatterTestCase, self).tearDown()
-        log.NovaLogger.manager.loggerDict = {}
 
     def test_uncontextualized_log(self):
         self.log.info("foo")
@@ -102,30 +114,15 @@ class NovaFormatterTestCase(test.TestCase):
 class NovaLoggerTestCase(test.TestCase):
     def setUp(self):
         super(NovaLoggerTestCase, self).setUp()
-        self.flags(default_log_levels=["nova-test=AUDIT"], verbose=False)
+        levels = FLAGS.default_log_levels
+        levels.append("nova-test=AUDIT")
+        self.flags(default_log_levels=levels,
+                   verbose=True)
         self.log = log.getLogger('nova-test')
 
-    def tearDown(self):
-        super(NovaLoggerTestCase, self).tearDown()
-        log.NovaLogger.manager.loggerDict = {}
-
     def test_has_level_from_flags(self):
         self.assertEqual(log.AUDIT, self.log.level)
 
     def test_child_log_has_level_of_parent_flag(self):
         l = log.getLogger('nova-test.foo')
         self.assertEqual(log.AUDIT, l.level)
-
-
-class VerboseLoggerTestCase(test.TestCase):
-    def setUp(self):
-        super(VerboseLoggerTestCase, self).setUp()
-        self.flags(default_log_levels=["nova.test=AUDIT"], verbose=True)
-        self.log = log.getLogger('nova.test')
-
-    def tearDown(self):
-        super(VerboseLoggerTestCase, self).tearDown()
-        log.NovaLogger.manager.loggerDict = {}
-
-    def test_will_be_verbose_if_named_nova_and_verbose_flag_set(self):
-        self.assertEqual(log.DEBUG, self.log.level)

nova/twistd.py

@@ -148,6 +148,7 @@ def WrapTwistedOptions(wrapped):
                 options.insert(0, '')
 
             args = FLAGS(options)
+            logging.setup()
             argv = args[1:]
             # ignore subcommands
 
@@ -258,7 +259,6 @@ def serve(filename):
         print 'usage: %s [options] [start|stop|restart]' % argv[0]
         sys.exit(1)
 
-    logging.basicConfig()
     logging.debug(_("Full set of FLAGS:"))
     for flag in FLAGS:
         logging.debug("%s : %s" % (flag, FLAGS.get(flag, None)))

nova/utils.py

@@ -55,7 +55,7 @@ def import_class(import_str):
         __import__(mod_str)
         return getattr(sys.modules[mod_str], class_str)
     except (ImportError, ValueError, AttributeError), exc:
-        logging.debug(_('Inner Exception: %s'), exc)
+        LOG.debug(_('Inner Exception: %s'), exc)
         raise exception.NotFound(_('Class %s cannot be found') % class_str)
 
 

nova/wsgi.py

@@ -59,7 +59,6 @@ class Server(object):
     """Server class to manage multiple WSGI sockets and applications."""
 
     def __init__(self, threads=1000):
-        logging.basicConfig()
         self.pool = eventlet.GreenPool(threads)
 
     def start(self, application, port, host='0.0.0.0', backlog=128):

run_tests.py

@@ -27,6 +27,7 @@ from nose import result
 from nose import core
 
 from nova import log as logging
+from nova.tests import fake_flags
 
 
 class NovaTestResult(result.TextTestResult):
@@ -60,7 +61,7 @@ class NovaTestRunner(core.TextTestRunner):
 
 
 if __name__ == '__main__':
-    logging.basicConfig()
+    logging.setup()
     c = config.Config(stream=sys.stdout,
                       env=os.environ,
                       verbosity=3,

run_tests.sh

@@ -40,7 +40,7 @@ done
 function run_tests {
   # Just run the test suites in current environment
   ${wrapper} rm -f nova.sqlite
-  ${wrapper} $NOSETESTS 2> run_tests.err.log
+  ${wrapper} $NOSETESTS
 }
 
 NOSETESTS="python run_tests.py $noseargs"