Merge lp:~vishvananda/nova/log-fix into lp:~hudson-openstack/nova/trunk

[Vish Ishaya]

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

[termie (termie)]

I will dive into this again in the morning, but what strikes me right away is that it feels unusual for logging to require adding an additional "initialized" attribute to Flags, my instinct is that this is a problem solvable by good practice rather than by force. If you'd like to explain further why it that needs to be done, that'd be swell and will make it easier to review again in the morning.

review: Needs Information

[Vish Ishaya (vishvananda)]

The main issue is that how logging is configured is heavily dependent on flags. There are a number of ways to get into our code:
a) nova-* bin files
b) tests through nose
c) external code importing files

We can do all configuration without the initialized flag if we do something like
import sys
from nova import flags
flags.FLAGS(sys.argv)
from nova import log as logging

at the top of every file that may be run from the command line. I find this ugly and fragile. If someone tries to use our code and fails to do these commands, logging will break. Also the flags are modified in various places, including tests, and nova-api after loading the paste.deploy conf.

An alternative to the initialized attribute is to cache the values of the relevant logging flags, and just check them for changes each time we log. I'm a little concerned about the performance of this option, especially for the default_log_levels flag which is a list and potentially expensive to check for changes every time we want to write a log message.

Perhaps the best option would be to put a logging_setup() in the end of flags.call(), so it will reset the logging conf after loading flags.

[Vish Ishaya (vishvananda)]

Ok I switched it to the Final option above. To reset the logging config because the flags have changed, there is a logging.reset() method.

I'm calling the method automatically at the end of flag parsing, but if this seems too messy, then we can manually add a logging.reset() after each call to FLAGS(sys.argv)

[Thierry Carrez (ttx)]

This is currently not fixing bug 721285.

Calling logging.reset() does not actually reset the logging level for instances of NovaLogger based on --verbose flag, since NovaLogger.setup_from_flags() does only look into --default_log_levels. NovaLogger should probably setLevel based on the contents of --verbose like NovaRootLogger does.

review: Needs Fixing

[Todd Willey (xtoddx)]

You can wipe out all references to basicConfig in the log module. All the logging.basicConfig call does is set up handlers for the root logger if they don't exist yet. Since NovaRootLogger will always have handlers, it becomes a no-op without having to re-define it. So you can remove
 * The definition of basicConfig
 * Setting the logging.basicConfig function
 * The check in the top-level audit() function that calls basicConfig

By returning on the first call to 'error' in the NovaLogger.exception, you stop environment dumps.

You should set the "nova" value of loggerDict to be the root logger as well, otherwise you'll get a new instance when you call logging.getLogger("nova"). It will require fixing the parent links in other loggers, and possibly using the same locking mechanics (see logging). That will also let the loop in reset find the root logger.

Instead of checking the class of loggers in the 'reset' function, you should probably check if they have a 'setup_from_flags' function, since it allows better duck-typing. It would also keep you from making the explicit call to the root logger.

I'd also vote for keeping the call to reset() away from the flags library, and put in in the binaries immediately after they call FLAGS(). Also, nova-api is changing soon so that it doesn't mangle flags (ttx has a branch).

[Todd Willey (xtoddx)]

To address TTX's point, I think both the root logger and NovaLogger instances should look at both --verbose and --default_log_levels, with default_log_levels having higher priority.

[Vish Ishaya (vishvananda)]

> This is currently not fixing bug 721285.
>
> Calling logging.reset() does not actually reset the logging level for
> instances of NovaLogger based on --verbose flag, since
> NovaLogger.setup_from_flags() does only look into --default_log_levels.
> NovaLogger should probably setLevel based on the contents of --verbose like
> NovaRootLogger does.

If a logger is explicitly set to a value, verbose should have no affect on it. If a logger has the value NOTSET, the root logger will pick it up and log it according to its own verbosity, so we don't need to set the individual loggers separately. That said, if the flags change to remove default_log_levels, then the reset will not pick it up, so I'll set it back to notset in that case.

[Vish Ishaya (vishvananda)]

> You can wipe out all references to basicConfig in the log module. All the
> logging.basicConfig call does is set up handlers for the root logger if they
> don't exist yet. Since NovaRootLogger will always have handlers, it becomes a
> no-op without having to re-define it. So you can remove
> * The definition of basicConfig
> * Setting the logging.basicConfig function
> * The check in the top-level audit() function that calls basicConfig

done.

>
> By returning on the first call to 'error' in the NovaLogger.exception, you
> stop environment dumps.

good catch

>
> You should set the "nova" value of loggerDict to be the root logger as well,
> otherwise you'll get a new instance when you call logging.getLogger("nova").
> It will require fixing the parent links in other loggers, and possibly using
> the same locking mechanics (see logging). That will also let the loop in
> reset find the root logger.

Good call.

>
> Instead of checking the class of loggers in the 'reset' function, you should
> probably check if they have a 'setup_from_flags' function, since it allows
> better duck-typing. It would also keep you from making the explicit call to
> the root logger.

The explicit call was fixed by above. Not sure that i see the value of duck-typing here.

>
> I'd also vote for keeping the call to reset() away from the flags library, and
> put in in the binaries immediately after they call FLAGS(). Also, nova-api is
> changing soon so that it doesn't mangle flags (ttx has a branch).

I'm ok with this although i find it annoying that we have to put this code in multiple places. Perhaps a utils.py function called parse_flags that does both?

[Todd Willey (xtoddx)]

I'd be good with with a method in utils that does both flag parsing & log reset.

[Vish Ishaya (vishvananda)]

As per Todd and termie's suggestions, I put in an explicit logging.setup after each call to FLAGS(). I also put the flag parsing directly into the bin files as this is a bit more explicit. As it is now, logging doesn't do anything on import except for override the type of the default logger. Everything else happens in .setup()

[termie (termie)]

594: extra newline was added
860: necessary newline was removed

It'd be nice to have the modifications to fake_flags.py "tests.log" and "tests.sqlite" be taken out of this patch.

review: Needs Fixing

[termie (termie)]

(as well as the removal of the db in run_tests.py)

[lp:~vishvananda/nova/log-fix]

723. By Vish Ishaya on 2011-02-22

remove changes to test db

[termie (termie)]

those numbers are now 585 and 848...

[Vish Ishaya (vishvananda)]

> those numbers are now 585 and 848...

fixed

[lp:~vishvananda/nova/log-fix]

724. By Vish Ishaya on 2011-02-22

fixed newline and moved import fake_flags into run_tests where it makes more sense

[termie (termie)]

lgtm

review: Approve

[Devin Carlen (devcamcar)]

lgtm

review: Approve

[Thierry Carrez (ttx)]

Tested & fixes bug 721285 alright now !

review: Approve

=== modified file 'bin/nova-ajax-console-proxy'
--- bin/nova-ajax-console-proxy	2011-01-10 21:44:45 +0000
+++ bin/nova-ajax-console-proxy	2011-02-22 00:22:48 +0000
@@ -25,7 +25,6 @@
 
 import exceptions
 import gettext
-import logging
 import os
 import sys
 import time
@@ -130,6 +129,7 @@
 if __name__ == '__main__':
     utils.default_flagfile()
     FLAGS(sys.argv)
+    logging.setup()
     server = wsgi.Server()
     acp = AjaxConsoleProxy()
     acp.register_listeners()

=== modified file 'bin/nova-api'
--- bin/nova-api	2011-01-21 21:10:26 +0000
+++ bin/nova-api	2011-02-22 00:22:48 +0000
@@ -39,9 +39,7 @@
 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 @@
         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 @@
 
 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')

=== modified file 'bin/nova-combined'
--- bin/nova-combined	2011-02-15 00:11:29 +0000
+++ bin/nova-combined	2011-02-22 00:22:48 +0000
@@ -49,7 +49,7 @@
 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 @@
         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)

=== modified file 'bin/nova-compute'
--- bin/nova-compute	2010-12-15 19:02:33 +0000
+++ bin/nova-compute	2011-02-22 00:22:48 +0000
@@ -36,10 +36,14 @@
 
 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()

=== modified file 'bin/nova-console'
--- bin/nova-console	2011-01-05 20:16:14 +0000
+++ bin/nova-console	2011-02-22 00:22:48 +0000
@@ -35,10 +35,14 @@
 
 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()

=== modified file 'bin/nova-dhcpbridge'
--- bin/nova-dhcpbridge	2011-01-24 15:19:51 +0000
+++ bin/nova-dhcpbridge	2011-02-22 00:22:48 +0000
@@ -102,7 +102,7 @@
     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

=== modified file 'bin/nova-direct-api'
--- bin/nova-direct-api	2011-01-18 13:48:50 +0000
+++ bin/nova-direct-api	2011-02-22 00:22:48 +0000
@@ -35,6 +35,7 @@
 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 @@
 if __name__ == '__main__':
     utils.default_flagfile()
     FLAGS(sys.argv)
+    logging.setup()
 
     direct.register_service('compute', compute_api.API())
     direct.register_service('reflect', direct.Reflection())

=== modified file 'bin/nova-import-canonical-imagestore'
--- bin/nova-import-canonical-imagestore	2010-12-14 23:22:03 +0000
+++ bin/nova-import-canonical-imagestore	2011-02-22 00:22:48 +0000
@@ -41,6 +41,7 @@
 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 @@
     """Main entry point."""
     utils.default_flagfile()
     argv = FLAGS(sys.argv)
+    logging.setup()
     images = get_images()
 
     if len(argv) == 2:

=== modified file 'bin/nova-instancemonitor'
--- bin/nova-instancemonitor	2011-01-04 05:26:41 +0000
+++ bin/nova-instancemonitor	2011-02-22 00:22:48 +0000
@@ -41,9 +41,6 @@
 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')
 
 

=== modified file 'bin/nova-manage'
--- bin/nova-manage	2011-02-17 21:39:03 +0000
+++ bin/nova-manage	2011-02-22 00:22:48 +0000
@@ -86,8 +86,6 @@
 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 @@
     """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:

=== modified file 'bin/nova-network'
--- bin/nova-network	2010-12-15 19:02:33 +0000
+++ bin/nova-network	2011-02-22 00:22:48 +0000
@@ -36,10 +36,14 @@
 
 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()

=== modified file 'bin/nova-scheduler'
--- bin/nova-scheduler	2010-12-15 19:02:33 +0000
+++ bin/nova-scheduler	2011-02-22 00:22:48 +0000
@@ -36,10 +36,14 @@
 
 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()

=== modified file 'bin/nova-volume'
--- bin/nova-volume	2010-12-15 19:02:33 +0000
+++ bin/nova-volume	2011-02-22 00:22:48 +0000
@@ -36,10 +36,14 @@
 
 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()

=== modified file 'nova/api/openstack/auth.py'
--- nova/api/openstack/auth.py	2011-02-18 22:35:12 +0000
+++ nova/api/openstack/auth.py	2011-02-22 00:22:48 +0000
@@ -19,7 +19,6 @@
 import hashlib
 import json
 import time
-import logging
 
 import webob.exc
 import webob.dec

=== modified file 'nova/api/openstack/backup_schedules.py'
--- nova/api/openstack/backup_schedules.py	2011-01-03 23:46:55 +0000
+++ nova/api/openstack/backup_schedules.py	2011-02-22 00:22:48 +0000
@@ -15,7 +15,6 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
-import logging
 import time
 
 from webob import exc

=== modified file 'nova/api/openstack/images.py'
--- nova/api/openstack/images.py	2011-01-13 19:48:01 +0000
+++ nova/api/openstack/images.py	2011-02-22 00:22:48 +0000
@@ -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

=== modified file 'nova/api/openstack/servers.py'
--- nova/api/openstack/servers.py	2011-02-18 22:36:01 +0000
+++ nova/api/openstack/servers.py	2011-02-22 00:22:48 +0000
@@ -33,7 +33,6 @@
 
 
 LOG = logging.getLogger('server')
-LOG.setLevel(logging.DEBUG)
 
 
 FLAGS = flags.FLAGS

=== modified file 'nova/api/openstack/shared_ip_groups.py'
--- nova/api/openstack/shared_ip_groups.py	2011-01-11 07:38:40 +0000
+++ nova/api/openstack/shared_ip_groups.py	2011-02-22 00:22:48 +0000
@@ -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

=== modified file 'nova/api/openstack/zones.py'
--- nova/api/openstack/zones.py	2011-02-15 03:02:26 +0000
+++ nova/api/openstack/zones.py	2011-02-22 00:22:48 +0000
@@ -14,7 +14,6 @@
 #    under the License.
 
 import common
-import logging
 
 from nova import flags
 from nova import wsgi

=== modified file 'nova/console/manager.py'
--- nova/console/manager.py	2011-01-20 17:52:02 +0000
+++ nova/console/manager.py	2011-02-22 00:22:48 +0000
@@ -20,11 +20,11 @@
 """
 
 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

=== modified file 'nova/console/xvp.py'
--- nova/console/xvp.py	2011-01-20 17:52:02 +0000
+++ nova/console/xvp.py	2011-02-22 00:22:48 +0000
@@ -20,7 +20,6 @@
 """
 
 import fcntl
-import logging
 import os
 import signal
 import subprocess
@@ -31,6 +30,7 @@
 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',

=== modified file 'nova/log.py'
--- nova/log.py	2011-02-18 09:24:55 +0000
+++ nova/log.py	2011-02-22 00:22:48 +0000
@@ -65,6 +65,7 @@
 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 @@
     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 @@
         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 @@
     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 @@
         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 @@
             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 @@
 _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)

=== modified file 'nova/service.py'
--- nova/service.py	2011-01-27 19:52:10 +0000
+++ nova/service.py	2011-02-22 00:22:48 +0000
@@ -214,9 +214,6 @@
 
 
 def serve(*services):
-    FLAGS(sys.argv)
-    logging.basicConfig()
-
     if not services:
         services = [Service.create()]
 

=== modified file 'nova/test.py'
--- nova/test.py	2011-01-26 21:58:24 +0000
+++ nova/test.py	2011-02-22 00:22:48 +0000
@@ -32,9 +32,9 @@
 from nova import db
 from nova import fakerabbit
 from nova import flags
+from nova import log as logging
 from nova import rpc
 from nova.network import manager as network_manager
-from nova.tests import fake_flags
 
 
 FLAGS = flags.FLAGS

=== modified file 'nova/tests/fake_flags.py'
--- nova/tests/fake_flags.py	2011-01-18 23:39:24 +0000
+++ nova/tests/fake_flags.py	2011-02-22 00:22:48 +0000
@@ -41,3 +41,4 @@
 FLAGS.verbose = True
 FLAGS.sql_connection = 'sqlite:///nova.sqlite'
 FLAGS.use_ipv6 = True
+FLAGS.logfile = 'tests.log'

=== modified file 'nova/tests/test_auth.py'
--- nova/tests/test_auth.py	2011-01-04 05:23:35 +0000
+++ nova/tests/test_auth.py	2011-02-22 00:22:48 +0000
@@ -327,15 +327,6 @@
 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'

=== modified file 'nova/tests/test_console.py'
--- nova/tests/test_console.py	2011-01-15 01:44:47 +0000
+++ nova/tests/test_console.py	2011-02-22 00:22:48 +0000
@@ -21,7 +21,6 @@
 """
 
 import datetime
-import logging
 
 from nova import context
 from nova import db
@@ -38,7 +37,6 @@
 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)

=== modified file 'nova/tests/test_direct.py'
--- nova/tests/test_direct.py	2011-01-08 00:05:06 +0000
+++ nova/tests/test_direct.py	2011-02-22 00:22:48 +0000
@@ -19,7 +19,6 @@
 """Tests for Direct API."""
 
 import json
-import logging
 
 import webob
 

=== modified file 'nova/tests/test_localization.py'
--- nova/tests/test_localization.py	2011-01-27 22:54:59 +0000
+++ nova/tests/test_localization.py	2011-02-22 00:22:48 +0000
@@ -15,7 +15,6 @@
 #    under the License.
 
 import glob
-import logging
 import os
 import re
 import sys

=== modified file 'nova/tests/test_log.py'
--- nova/tests/test_log.py	2011-02-16 09:02:17 +0000
+++ nova/tests/test_log.py	2011-02-22 00:22:48 +0000
@@ -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 @@
         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 @@
         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 @@
                    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 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)

=== modified file 'nova/twistd.py'
--- nova/twistd.py	2011-02-14 22:19:15 +0000
+++ nova/twistd.py	2011-02-22 00:22:48 +0000
@@ -148,6 +148,7 @@
                 options.insert(0, '')
 
             args = FLAGS(options)
+            logging.setup()
             argv = args[1:]
             # ignore subcommands
 
@@ -258,7 +259,6 @@
         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)))

=== modified file 'nova/utils.py'
--- nova/utils.py	2011-02-17 22:09:26 +0000
+++ nova/utils.py	2011-02-22 00:22:48 +0000
@@ -55,7 +55,7 @@
         __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)
 
 

=== modified file 'nova/wsgi.py'
--- nova/wsgi.py	2011-01-21 21:10:26 +0000
+++ nova/wsgi.py	2011-02-22 00:22:48 +0000
@@ -59,7 +59,6 @@
     """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):

=== modified file 'run_tests.py'
--- run_tests.py	2011-01-31 05:38:58 +0000
+++ run_tests.py	2011-02-22 00:22:48 +0000
@@ -27,6 +27,7 @@
 from nose import core
 
 from nova import log as logging
+from nova.tests import fake_flags
 
 
 class NovaTestResult(result.TextTestResult):
@@ -60,7 +61,7 @@
 
 
 if __name__ == '__main__':
-    logging.basicConfig()
+    logging.setup()
     c = config.Config(stream=sys.stdout,
                       env=os.environ,
                       verbosity=3,

=== modified file 'run_tests.sh'
--- run_tests.sh	2011-01-31 05:55:32 +0000
+++ run_tests.sh	2011-02-22 00:22:48 +0000
@@ -40,7 +40,7 @@
 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"