fixes for various logging errors and issues

nova/api/openstack/auth.py

@@ -19,7 +19,6 @@ import datetime
 import hashlib
 import json
 import time
-import logging
 
 import webob.exc
 import webob.dec

nova/api/openstack/backup_schedules.py

@@ -15,7 +15,6 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
-import logging
 import time
 
 from webob import exc

nova/api/openstack/images.py

@@ -15,8 +15,6 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
-import logging
-
 from webob import exc
 
 from nova import compute

nova/api/openstack/servers.py

@@ -33,7 +33,6 @@ import nova.api.openstack
 
 
 LOG = logging.getLogger('server')
-LOG.setLevel(logging.DEBUG)
 
 
 FLAGS = flags.FLAGS

nova/api/openstack/shared_ip_groups.py

@@ -15,8 +15,6 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
-import logging
-
 from webob import exc
 
 from nova import wsgi

nova/api/openstack/zones.py

@@ -14,7 +14,6 @@
 #    under the License.
 
 import common
-import logging
 
 from nova import flags
 from nova import wsgi

nova/console/manager.py

@@ -20,11 +20,11 @@ Console Proxy Service
 """
 
 import functools
-import logging
 import socket
 
 from nova import exception
 from nova import flags
+from nova import log as logging
 from nova import manager
 from nova import rpc
 from nova import utils

nova/console/xvp.py

@@ -20,7 +20,6 @@ XVP (Xenserver VNC Proxy) driver.
 """
 
 import fcntl
-import logging
 import os
 import signal
 import subprocess
@@ -31,6 +30,7 @@ from nova import context
 from nova import db
 from nova import exception
 from nova import flags
+from nova import log as logging
 from nova import utils
 
 flags.DEFINE_string('console_xvp_conf_template',

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,7 +117,22 @@ 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 exactly "nova", or a child logger, honor the verbose flag
+    if (name == "nova" or name.startswith("nova.")) and FLAGS.verbose:
+        return 'DEBUG'
+    for pair in FLAGS.default_log_levels:
+        logger, _sep, level = 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'
+
+
+def _get_log_file_path(binary=None):
     if FLAGS.logfile:
         return FLAGS.logfile
     if FLAGS.logdir:
@@ -126,22 +141,13 @@ def get_log_file_path(binary=None):
 
 
 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)
+    pass
+
+
+logging.basicConfig = basicConfig
+_syslog = SysLogHandler(address='/dev/log')
+_filelog = None
+_streamlog = StreamHandler()
 
 
 class NovaLogger(logging.Logger):
@@ -151,23 +157,24 @@ 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.initialized = False
+        if flags.FlagValues.initialized:
+            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'
-        for pair in FLAGS.default_log_levels:
-            logger, _sep, level = 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'
+    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"""
@@ -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/test.py

@@ -60,6 +60,8 @@ class TestCase(unittest.TestCase):
     def setUp(self):
         """Run before each test method to initialize test environment"""
         super(TestCase, self).setUp()
+        # NOTE(vish): pretend like we've loaded flags from command line
+        flags.FlagValues.initialized = True
         # NOTE(vish): We need a better method for creating fixtures for tests
         #             now that we have some required db setup for the system
         #             to work properly.

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):
-        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,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.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 +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.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 +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)

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.info(_('Inner Exception: %s'), exc)
         raise exception.NotFound(_('Class %s cannot be found') % class_str)
 
 

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,