fixes for various logging errors and issues

nova/flags.py

@@ -38,6 +38,7 @@ class FlagValues(gflags.FlagValues):
     defined after the initial parsing.
 
     """
+    initialized = False
 
     def __init__(self, extra_context=None):
         gflags.FlagValues.__init__(self)
@@ -45,6 +46,8 @@ class FlagValues(gflags.FlagValues):
         self.__dict__['__was_already_parsed'] = False
         self.__dict__['__stored_argv'] = []
         self.__dict__['__extra_context'] = extra_context
+        # NOTE(vish): force a pseudo flag to keep track of whether
+        #             flags have been parsed already
 
     def __call__(self, argv):
         # We're doing some hacky stuff here so that we don't have to copy
@@ -90,6 +93,7 @@ class FlagValues(gflags.FlagValues):
         self.__dict__['__stored_argv'] = original_argv
         self.__dict__['__was_already_parsed'] = True
         self.ClearDirty()
+        FlagValues.initialized = True
         return args
 
     def Reset(self):

nova/log.py

@@ -117,45 +117,7 @@ def _get_binary_name():
     return os.path.basename(inspect.stack()[-1][1])
 
 
-def get_log_file_path(binary=None):
+def _get_level_from_flags(name):
-    if FLAGS.logfile:
-        return FLAGS.logfile
-    if FLAGS.logdir:
-        binary = binary or _get_binary_name()
-        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.
-
-    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)
-
-    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'
@@ -169,6 +131,51 @@ class NovaLogger(logging.Logger):
             return level
     return 'INFO'
 
+
+def _get_log_file_path(binary=None):
+    if FLAGS.logfile:
+        return FLAGS.logfile
+    if FLAGS.logdir:
+        binary = binary or _get_binary_name()
+        return '%s.log' % (os.path.join(FLAGS.logdir, binary),)
+
+
+def basicConfig():
+    pass
+
+
+logging.basicConfig = basicConfig
+_syslog = SysLogHandler(address='/dev/log')
+_filelog = None
+_streamlog = StreamHandler()
+
+
+class NovaLogger(logging.Logger):
+    """
+    NovaLogger manages request context and formatting.
+
+    This becomes the class that is instanciated by logging.getLogger.
+    """
+    def __init__(self, name, level=NOTSET):
+        logging.Logger.__init__(self, name, level)
+        self.initialized = False
+        if flags.FlagValues.initialized:
+            self._setup_from_flags()
+
+    def _setup_from_flags(self):
+        """Setup logger from flags"""
+        level_name = _get_level_from_flags(self.name)
+        self.setLevel(globals()[level_name])
+        self.initialized = True
+        if not logging.root.initialized:
+            logging.root._setup_from_flags()
+
+    def isEnabledFor(self, level):
+        """Reset level after flags have been loaded"""
+        if not self.initialized and flags.FlagValues.initialized:
+            self._setup_from_flags()
+        return logging.Logger.isEnabledFor(self, level)
+
     def _log(self, level, msg, args, exc_info=None, extra=None, context=None):
         """Extract context from any log call"""
         if not extra:
@@ -176,12 +183,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"""
@@ -192,7 +199,7 @@ class NovaLogger(logging.Logger):
         """Logging.exception doesn't handle kwargs, so breaks context"""
         if not kwargs.get('exc_info'):
             kwargs['exc_info'] = 1
-        self.error(msg, *args, **kwargs)
+        return self.error(msg, *args, **kwargs)
         # NOTE(todd): does this really go here, or in _log ?
         extra = kwargs.get('extra')
         if not extra:
@@ -209,6 +216,8 @@ class NovaLogger(logging.Logger):
 
 
 def handle_exception(type, value, tb):
+    if len(logging.root.handlers) == 0:
+        logging.root.addHandler(_streamlog)
     logging.root.critical(str(value), exc_info=(type, value, tb))
 
 
@@ -216,15 +225,6 @@ 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,6 +271,33 @@ class NovaFormatter(logging.Formatter):
 _formatter = NovaFormatter()
 
 
+class NovaRootLogger(NovaLogger):
+    def __init__(self, name, level=NOTSET):
+        NovaLogger.__init__(self, name, level)
+        self.addHandler(_streamlog)
+
+    def _setup_from_flags(self):
+        """Setup logger from flags"""
+        global _filelog
+        if FLAGS.use_syslog:
+            self.addHandler(_syslog)
+        logpath = _get_log_file_path()
+        if logpath:
+            if not _filelog:
+                _filelog = WatchedFileHandler(logpath)
+            self.addHandler(_filelog)
+            self.removeHandler(_streamlog)
+        return NovaLogger._setup_from_flags(self)
+
+
+if not isinstance(logging.root, NovaRootLogger):
+    for handler in logging.root.handlers:
+        logging.root.removeHandler(handler)
+    logging.root = NovaRootLogger("nova")
+    NovaLogger.root = logging.root
+    NovaLogger.manager.root = logging.root
+
+
 def audit(msg, *args, **kwargs):
     """Shortcut for logging to root log with sevrity 'AUDIT'."""
     if len(logging.root.handlers) == 0:

nova/tests/fake_flags.py

@@ -41,3 +41,5 @@ FLAGS.iscsi_num_targets = 8
 FLAGS.verbose = True
 FLAGS.sql_connection = 'sqlite:///nova.sqlite'
 FLAGS.use_ipv6 = True
+FLAGS.logfile = 'run_tests.err'
+flags.FlagValues.initialized = True

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):
+    def test_name_is_nova(self):
-        self.assertEqual("nova.root", self.log.name)
+        self.assertEqual("nova", self.log.name)
 
     def test_handlers_have_nova_formatter(self):
         formatters = []
@@ -45,25 +44,38 @@ 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)
+        self.log.initialized = False
+        log.audit("foo", context=_fake_context())
+        self.assertEqual(log.DEBUG, self.log.level)
+
+    def test_will_not_be_verbose_if_verbose_flag_not_set(self):
+        self.flags(verbose=False)
+        self.log.initialized = False
+        log.audit("foo", context=_fake_context())
+        self.assertEqual(log.INFO, self.log.level)
+
 
 class LogHandlerTestCase(test.TestCase):
     def test_log_path_logdir(self):
-        self.flags(logdir='/some/path')
+        self.flags(logdir='/some/path', logfile=None)
-        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_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 +88,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.handler = log.StreamHandler(self.stream)
-        self.log.addHandler(handler)
+        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 +116,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)

run_tests.py

@@ -26,8 +26,6 @@ from nose import config
 from nose import result
 from nose import core
 
-from nova import log as logging
-
 
 class NovaTestResult(result.TextTestResult):
     def __init__(self, *args, **kw):
@@ -60,7 +58,8 @@ class NovaTestRunner(core.TextTestRunner):
 
 
 if __name__ == '__main__':
-    logging.basicConfig()
+    if os.path.exists("nova.sqlite"):
+        os.unlink("nova.sqlite")
     c = config.Config(stream=sys.stdout,
                       env=os.environ,
                       verbosity=3,