Merge lp:~ken-pepple/nova/lp718360 into lp:~hudson-openstack/nova/trunk

[Ken Pepple]

fixed debug level logging in nova/utils.py

this is tricky and a bit brittle -- the problem we are seeing is that when you run nova-compute, you are importing nova/utils.py before you've parsed FLAGS, so you can't set the correct LOG.level if you've added the --verbose flag (it always stays at the default 20 / INFO value). To fix, I've brought in flags to utils.py and had it parse the sys.argv ... which will work most of the time. The one case were it will not work is when you've let haven't specified flags or a flagfile on the command line.

Also updated crypto.py and rpc.py, which exhibited similar problems.

[Todd Willey (xtoddx)]

Is there anywhere else FLAGS() is being called in library code instead of the binaries? I'm thinking it may make testing more brittle, and should probably be avoided.

review: Needs Information

[Jay Pipes (jaypipes)]

> Is there anywhere else FLAGS() is being called in library code instead of the
> binaries? I'm thinking it may make testing more brittle, and should probably
> be avoided.

Yes. Pretty much everywhere.

jpipes@serialcoder:~/repos/nova/trunk/nova$ ack-grep --ignore-dir=tests -l "FLAGS = flags.FLAGS"
auth/manager.py
auth/ldapdriver.py
cloudpipe/pipelib.py
scheduler/manager.py
scheduler/driver.py
scheduler/simple.py
test.py
compute/instance_types.py
compute/monitor.py
compute/manager.py
compute/api.py
log.py
image/s3.py
image/glance.py
virt/libvirt_conn.py
virt/xenapi_conn.py
virt/disk.py
virt/connection.py
virt/hyperv.py
virt/xenapi/vm_utils.py
virt/xenapi/volume_utils.py
virt/images.py
db/base.py
db/api.py
db/migration.py
db/sqlalchemy/session.py
db/sqlalchemy/models.py
db/sqlalchemy/api.py
db/sqlalchemy/migration.py
crypto.py
network/manager.py
network/api.py
network/linux_net.py
manager.py
objectstore/handler.py
objectstore/bucket.py
objectstore/image.py
service.py
quota.py
wsgi.py
volume/manager.py
volume/san.py
volume/api.py
volume/driver.py
rpc.py
api/ec2/metadatarequesthandler.py
api/ec2/cloud.py
api/ec2/__init__.py
api/openstack/auth.py
api/openstack/__init__.py
api/openstack/servers.py
api/openstack/images.py
twistd.py
console/xvp.py
console/manager.py
console/api.py

[Jay Pipes (jaypipes)]

I suppose you were only looking for places in the library code that call FLAGS() with something?

jpipes@serialcoder:~/repos/nova/trunk/nova$ ack-grep --ignore-dir=tests "FLAGS\("
service.py
217: FLAGS(sys.argv)

twistd.py
150: args = FLAGS(options)

[Todd Willey (xtoddx)]

Right, and both service and twistd are helpers for binaries. I don't think library code should be calling FLAGS(). I also don't see where sys is used in crypto.

I'm not sure what the codepath is that needs to be verbose more quickly, but I suspect reordering operations to call FLAGS() and logging.basicConfig() earlier than running any code should work fine.

I also thought about manually setting up loggers to log debug messages with a StreamHandler that points to a CStringIO, so you hold the log in memory, then after you load flags you can dump its contents if you are verbose, or discard them if not.

[Vish Ishaya (vishvananda)]

The issue is that logging.basicConfig() needs to run before anything is imported to catch any import errors. Perhaps the binaries should actually import logging and run logging.basicConfig() at the top of the binary files instead of inside if name == __main__:

Another option is to actually configure the root loggers by default in our logging module as the python logging module does, so we don't have to wait for basicConfig. I'm a bit annoyed that our module breaks compatibility this way. If there is some way that we can replace the default logging.basicConfig with our logging.basicConfig it will solve this problem, because all of the warn/debug/info functions call logging.basicConfig.

On Feb 17, 2011, at 10:44 AM, Todd Willey wrote:

> Right, and both service and twistd are helpers for binaries. I don't think library code should be calling FLAGS(). I also don't see where sys is used in crypto.
>
> I'm not sure what the codepath is that needs to be verbose more quickly, but I suspect reordering operations to call FLAGS() and logging.basicConfig() earlier than running any code should work fine.
>
> I also thought about manually setting up loggers to log debug messages with a StreamHandler that points to a CStringIO, so you hold the log in memory, then after you load flags you can dump its contents if you are verbose, or discard them if not.
> --
> https://code.launchpad.net/~ken-pepple/nova/lp718360/+merge/49919
> You are subscribed to branch lp:nova.

[Ken Pepple (ken-pepple)]

vish -- i'd vote that we make the binaries import and run logging (as well as parse FLAGS so that we get --verbose option up front) ...

[Todd Willey (xtoddx)]

Won't failed imports raise an exception, and probably exit the binary? If somebody could show me a specific example I'd have more intelligent discourse on this matter.

[Todd Willey (xtoddx)]

This should be fixed in https://code.launchpad.net/~vishvananda/nova/log-fix/+merge/50554

review: Disapprove

Unmerged revisions

675. By Ken Pepple on 2011-02-16

removed unnecessary flag parse

674. By Ken Pepple on 2011-02-16

initialized FLAGS with sys.argv for LOG.debug to work

673. By Ken Pepple on 2011-02-15

fixed (?) logging issues in rpc and utils

672. By Ken Pepple on 2011-02-15

merged trunk

=== modified file 'nova/crypto.py'
--- nova/crypto.py	2011-01-04 05:23:35 +0000
+++ nova/crypto.py	2011-02-16 05:41:25 +0000
@@ -27,6 +27,7 @@
 import os
 import shutil
 import struct
+import sys
 import tempfile
 import time
 import utils
@@ -41,8 +42,10 @@
 from nova import log as logging
 
 
+FLAGS = flags.FLAGS
 LOG = logging.getLogger("nova.crypto")
-FLAGS = flags.FLAGS
+
+
 flags.DEFINE_string('ca_file', 'cacert.pem', _('Filename of root CA'))
 flags.DEFINE_string('key_file',
                     os.path.join('private', 'cakey.pem'),

=== modified file 'nova/utils.py'
--- nova/utils.py	2011-02-14 20:06:16 +0000
+++ nova/utils.py	2011-02-16 05:41:25 +0000
@@ -38,10 +38,12 @@
 from eventlet.green import subprocess
 
 from nova import exception
+from nova import flags
 from nova.exception import ProcessExecutionError
 from nova import log as logging
 
-
+FLAGS = flags.FLAGS
+FLAGS(sys.argv)
 LOG = logging.getLogger("nova.utils")
 TIME_FORMAT = "%Y-%m-%dT%H:%M:%SZ"