diff --git a/nova/flags.py b/nova/flags.py index f64a62da..2f3bdd67 100644 --- a/nova/flags.py +++ b/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): diff --git a/nova/log.py b/nova/log.py index 6b201ffc..12b695a4 100644 --- a/nova/log.py +++ b/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: diff --git a/nova/tests/fake_flags.py b/nova/tests/fake_flags.py index 1097488e..68b14a46 100644 --- a/nova/tests/fake_flags.py +++ b/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 diff --git a/nova/tests/test_auth.py b/nova/tests/test_auth.py index 35ffffb6..2a781703 100644 --- a/nova/tests/test_auth.py +++ b/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' diff --git a/nova/tests/test_console.py b/nova/tests/test_console.py index 85bf9445..49ff2441 100644 --- a/nova/tests/test_console.py +++ b/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) diff --git a/nova/tests/test_direct.py b/nova/tests/test_direct.py index 8a74b229..7656f539 100644 --- a/nova/tests/test_direct.py +++ b/nova/tests/test_direct.py @@ -19,7 +19,6 @@ """Tests for Direct API.""" import json -import logging import webob diff --git a/nova/tests/test_localization.py b/nova/tests/test_localization.py index 6992773f..393d7103 100644 --- a/nova/tests/test_localization.py +++ b/nova/tests/test_localization.py @@ -15,7 +15,6 @@ # under the License. import glob -import logging import os import re import sys diff --git a/nova/tests/test_log.py b/nova/tests/test_log.py index c2c9d777..ada8d0a5 100644 --- a/nova/tests/test_log.py +++ b/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) diff --git a/run_tests.py b/run_tests.py index 24786e8a..bf12c62c 100644 --- a/run_tests.py +++ b/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,