From 2f0339b9da07113fcae8077803c31927fbbd17fe Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Fri, 8 Oct 2010 17:57:13 -0700 Subject: [PATCH 01/26] Twisted pidfile and other flag parameters simply do not function on Windows. --- nova/twistd.py | 31 ++++++++++++++++--------------- 1 file changed, 16 insertions(+), 15 deletions(-) diff --git a/nova/twistd.py b/nova/twistd.py index 9511c231..29d75328 100644 --- a/nova/twistd.py +++ b/nova/twistd.py @@ -224,21 +224,22 @@ def serve(filename): logging.getLogger('amqplib').setLevel(logging.WARN) FLAGS.python = filename FLAGS.no_save = True - if not FLAGS.pidfile: - FLAGS.pidfile = '%s.pid' % name - elif FLAGS.pidfile.endswith('twistd.pid'): - FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', '%s.pid' % name) - # NOTE(vish): if we're running nodaemon, redirect the log to stdout - if FLAGS.nodaemon and not FLAGS.logfile: - FLAGS.logfile = "-" - if not FLAGS.logfile: - FLAGS.logfile = '%s.log' % name - elif FLAGS.logfile.endswith('twistd.log'): - FLAGS.logfile = FLAGS.logfile.replace('twistd.log', '%s.log' % name) - if not FLAGS.prefix: - FLAGS.prefix = name - elif FLAGS.prefix.endswith('twisted'): - FLAGS.prefix = FLAGS.prefix.replace('twisted', name) + if sys.platform != 'win32': + if not FLAGS.pidfile: + FLAGS.pidfile = '%s.pid' % name + elif FLAGS.pidfile.endswith('twistd.pid'): + FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', '%s.pid' % name) + # NOTE(vish): if we're running nodaemon, redirect the log to stdout + if FLAGS.nodaemon and not FLAGS.logfile: + FLAGS.logfile = "-" + if not FLAGS.logfile: + FLAGS.logfile = '%s.log' % name + elif FLAGS.logfile.endswith('twistd.log'): + FLAGS.logfile = FLAGS.logfile.replace('twistd.log', '%s.log' % name) + if not FLAGS.prefix: + FLAGS.prefix = name + elif FLAGS.prefix.endswith('twisted'): + FLAGS.prefix = FLAGS.prefix.replace('twisted', name) action = 'start' if len(argv) > 1: From fd166f7c4b2259715bf39357fee34a1a88be69de Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Wed, 13 Oct 2010 23:19:25 -0700 Subject: [PATCH 02/26] Added a unit test but not integrated it --- nova/tests/hyperv_unittest.py | 67 +++++++++++++++++++++++++++++++++++ 1 file changed, 67 insertions(+) create mode 100644 nova/tests/hyperv_unittest.py diff --git a/nova/tests/hyperv_unittest.py b/nova/tests/hyperv_unittest.py new file mode 100644 index 00000000..e5c6d719 --- /dev/null +++ b/nova/tests/hyperv_unittest.py @@ -0,0 +1,67 @@ +# vim: tabstop=4 shiftwidth=4 softtabstop=4 +# +# Copyright 2010 Cloud.com, Inc +# +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. +""" +Tests For Hyper-V driver +""" + +import random + +from nova import db +from nova import flags +from nova import test + +from nova.virt import hyperv + +FLAGS = flags.FLAGS +FLAGS.connection_type = 'hyperv' +# Redis is probably not running on Hyper-V host. +# Change this to the actual Redis host +FLAGS.redis_host = '127.0.0.1' + + +class HyperVTestCase(test.TrialTestCase): + """Test cases for the Hyper-V driver""" + def setUp(self): # pylint: disable-msg=C0103 + pass + + def test_create_destroy(self): + """Create a VM and destroy it""" + instance = {'internal_id' : random.randint(1, 1000000), + 'memory_mb' : '1024', + 'mac_address' : '02:12:34:46:56:67', + 'vcpus' : 2, + 'project_id' : 'fake', + 'instance_type' : 'm1.small'} + + instance_ref = db.instance_create(None, instance) + + conn = hyperv.get_connection(False) + conn._create_vm(instance_ref) # pylint: disable-msg=W0212 + found = [n for n in conn.list_instances() + if n == instance_ref['name']] + self.assertTrue(len(found) == 1) + info = conn.get_info(instance_ref['name']) + #Unfortunately since the vm is not running at this point, + #we cannot obtain memory information from get_info + self.assertEquals(info['num_cpu'], instance_ref['vcpus']) + + conn.destroy(instance_ref) + found = [n for n in conn.list_instances() + if n == instance_ref['name']] + self.assertTrue(len(found) == 0) + + def tearDown(self): # pylint: disable-msg=C0103 + pass From 70b422c2fb21a6bbdd495f6988288808037c87a8 Mon Sep 17 00:00:00 2001 From: Eric Day Date: Thu, 9 Dec 2010 13:59:50 -0800 Subject: [PATCH 03/26] Converted the instance table to use a uuid instead of a auto_increment ID and a random internal_id. I had to use a String(32) column with hex and not a String(16) with bytes because SQLAlchemy doesn't like non-unicode strings going in for String types. We could try another type, but I didn't want a primary_key on blob types. --- nova/tests/cloud_unittest.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/nova/tests/cloud_unittest.py b/nova/tests/cloud_unittest.py index 9886a244..f63eed65 100644 --- a/nova/tests/cloud_unittest.py +++ b/nova/tests/cloud_unittest.py @@ -113,7 +113,7 @@ class CloudTestCase(test.TrialTestCase): self.cloud.allocate_address(self.context) inst = db.instance_create(self.context, {}) fixed = self.network.allocate_fixed_ip(self.context, inst['id']) - ec2_id = cloud.internal_id_to_ec2_id(inst['internal_id']) + ec2_id = cloud.id_to_ec2_id(inst['id']) self.cloud.associate_address(self.context, instance_id=ec2_id, public_ip=address) @@ -289,7 +289,7 @@ class CloudTestCase(test.TrialTestCase): def test_update_of_instance_display_fields(self): inst = db.instance_create(self.context, {}) - ec2_id = cloud.internal_id_to_ec2_id(inst['internal_id']) + ec2_id = cloud.id_to_ec2_id(inst['id']) self.cloud.update_instance(self.context, ec2_id, display_name='c00l 1m4g3') inst = db.instance_get(self.context, inst['id']) From b378d7e28558262d6aefe578d805c952da329f05 Mon Sep 17 00:00:00 2001 From: Eric Day Date: Mon, 27 Dec 2010 12:19:36 -0800 Subject: [PATCH 04/26] Converted Volume model and operation to use UUIDs. --- nova/tests/test_cloud.py | 4 ++-- nova/tests/test_xenapi.py | 11 +++++------ 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/nova/tests/test_cloud.py b/nova/tests/test_cloud.py index ca400077..42344af1 100644 --- a/nova/tests/test_cloud.py +++ b/nova/tests/test_cloud.py @@ -127,9 +127,9 @@ class CloudTestCase(test.TestCase): result = self.cloud.describe_volumes(self.context) self.assertEqual(len(result['volumeSet']), 2) result = self.cloud.describe_volumes(self.context, - volume_id=[vol2['ec2_id']]) + volume_id=[vol2['id']]) self.assertEqual(len(result['volumeSet']), 1) - self.assertEqual(result['volumeSet'][0]['volumeId'], vol2['ec2_id']) + self.assertEqual(result['volumeSet'][0]['volumeId'], vol2['id']) db.volume_destroy(self.context, vol1['id']) db.volume_destroy(self.context, vol2['id']) diff --git a/nova/tests/test_xenapi.py b/nova/tests/test_xenapi.py index ed2e4ffd..900b9af2 100644 --- a/nova/tests/test_xenapi.py +++ b/nova/tests/test_xenapi.py @@ -79,8 +79,8 @@ class XenAPIVolumeTestCase(test.TestCase): helper = volume_utils.VolumeHelper helper.XenAPI = session.get_imported_xenapi() vol = self._create_volume() - info = helper.parse_volume_info(vol['ec2_id'], '/dev/sdc') - label = 'SR-%s' % vol['ec2_id'] + info = helper.parse_volume_info(vol['id'], '/dev/sdc') + label = 'SR-%s' % vol['id'] description = 'Test-SR' sr_ref = helper.create_iscsi_storage(session, info, label, description) srs = fake.get_all('SR') @@ -97,7 +97,7 @@ class XenAPIVolumeTestCase(test.TestCase): # oops, wrong mount point! self.assertRaises(volume_utils.StorageError, helper.parse_volume_info, - vol['ec2_id'], + vol['id'], '/dev/sd') db.volume_destroy(context.get_admin_context(), vol['id']) @@ -108,8 +108,7 @@ class XenAPIVolumeTestCase(test.TestCase): volume = self._create_volume() instance = db.instance_create(self.values) fake.create_vm(instance.name, 'Running') - result = conn.attach_volume(instance.name, volume['ec2_id'], - '/dev/sdc') + result = conn.attach_volume(instance.name, volume['id'], '/dev/sdc') def check(): # check that the VM has a VBD attached to it @@ -134,7 +133,7 @@ class XenAPIVolumeTestCase(test.TestCase): self.assertRaises(Exception, conn.attach_volume, instance.name, - volume['ec2_id'], + volume['id'], '/dev/sdc') def tearDown(self): From 6b6774f855b1e1f775498a29d3a1ad57cfa0a931 Mon Sep 17 00:00:00 2001 From: Trey Morris Date: Wed, 29 Dec 2010 18:30:01 -0600 Subject: [PATCH 05/26] moved check lock decorator to compute api level. altered openstack.test_servers according and wrote test for lock in tests.test_compute --- nova/tests/test_compute.py | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index bcb8a152..422d59da 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -170,3 +170,20 @@ class ComputeTestCase(test.TestCase): self.context, instance_id) self.compute.terminate_instance(self.context, instance_id) + + def test_lock(self): + """ensure locked instance cannot be changed""" + instance_id = self._create_instance() + self.compute.run_instance(self.context, instance_id) + self.compute.pause_instance(self.context, instance_id) + self.compute.lock_instance(self.context, instance_id) + + # pause should raise exception on locked instance + self.assertRaises(Exception, self.compute.unpause_instance, + self.context, instance_id) + + # test will fail if exception is raised + self.compute.unlock_instance(self.context, instance_id) + self.compute.unpause_instance(self.context, instance_id) + + self.compute.terminate_instance(self.context, instance_id) From 2bb4dacaaa5f4b5dd5d4391847b9a5c611058d8e Mon Sep 17 00:00:00 2001 From: Trey Morris Date: Wed, 29 Dec 2010 21:16:53 -0600 Subject: [PATCH 06/26] fixed up the compute lock test, was failing because the context was always admin --- nova/tests/test_compute.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index 422d59da..f914294f 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -175,15 +175,15 @@ class ComputeTestCase(test.TestCase): """ensure locked instance cannot be changed""" instance_id = self._create_instance() self.compute.run_instance(self.context, instance_id) - self.compute.pause_instance(self.context, instance_id) self.compute.lock_instance(self.context, instance_id) + non_admin_context = context.RequestContext(None, None, False, False) # pause should raise exception on locked instance - self.assertRaises(Exception, self.compute.unpause_instance, - self.context, instance_id) + self.assertRaises(Exception, self.compute.reboot_instance, + non_admin_context, instance_id) # test will fail if exception is raised self.compute.unlock_instance(self.context, instance_id) - self.compute.unpause_instance(self.context, instance_id) + self.compute.reboot_instance(non_admin_context, instance_id) self.compute.terminate_instance(self.context, instance_id) From 60544720ea11956909e86286f7f1910a88386c92 Mon Sep 17 00:00:00 2001 From: Trey Morris Date: Wed, 29 Dec 2010 22:08:38 -0600 Subject: [PATCH 07/26] altered the compute lock test --- nova/tests/test_compute.py | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index f914294f..78582b75 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -178,12 +178,14 @@ class ComputeTestCase(test.TestCase): self.compute.lock_instance(self.context, instance_id) non_admin_context = context.RequestContext(None, None, False, False) - # pause should raise exception on locked instance - self.assertRaises(Exception, self.compute.reboot_instance, - non_admin_context, instance_id) - # test will fail if exception is raised + # decorator for reboot should return False + ret_val = self.compute.reboot_instance(non_admin_context,instance_id) + self.assertEqual(ret_val, False) + + # decorator for pause should return the result of the function reboot self.compute.unlock_instance(self.context, instance_id) - self.compute.reboot_instance(non_admin_context, instance_id) + ret_val = self.compute.reboot_instance(non_admin_context,instance_id) + self.assertNotEqual(ret_val, None) self.compute.terminate_instance(self.context, instance_id) From 272ba34bd0aa0ca9d332dcb6467c2134b6ffb453 Mon Sep 17 00:00:00 2001 From: Trey Morris Date: Wed, 29 Dec 2010 22:16:34 -0600 Subject: [PATCH 08/26] fixed the compute lock test --- nova/tests/test_compute.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index 78582b75..993c4fd3 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -175,17 +175,17 @@ class ComputeTestCase(test.TestCase): """ensure locked instance cannot be changed""" instance_id = self._create_instance() self.compute.run_instance(self.context, instance_id) - self.compute.lock_instance(self.context, instance_id) non_admin_context = context.RequestContext(None, None, False, False) - # decorator for reboot should return False + # decorator should return False (fail) with locked nonadmin context + self.compute.lock_instance(self.context, instance_id) ret_val = self.compute.reboot_instance(non_admin_context,instance_id) self.assertEqual(ret_val, False) - # decorator for pause should return the result of the function reboot + # decorator should return None (success) with unlocked nonadmin context self.compute.unlock_instance(self.context, instance_id) ret_val = self.compute.reboot_instance(non_admin_context,instance_id) - self.assertNotEqual(ret_val, None) + self.assertEqual(ret_val, None) self.compute.terminate_instance(self.context, instance_id) From 6cd891b08b9bf079244bd640b7e685e392696635 Mon Sep 17 00:00:00 2001 From: Eric Day Date: Wed, 29 Dec 2010 20:30:36 -0800 Subject: [PATCH 09/26] Cleaned up the compute API, mostly consistency with other parts of the system and renaming redundant module names. --- nova/tests/test_compute.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index 348bb335..f7067b98 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -22,6 +22,7 @@ Tests For Compute import datetime import logging +from nova import compute from nova import context from nova import db from nova import exception @@ -29,7 +30,6 @@ from nova import flags from nova import test from nova import utils from nova.auth import manager -from nova.compute import api as compute_api FLAGS = flags.FLAGS @@ -44,7 +44,7 @@ class ComputeTestCase(test.TestCase): stub_network=True, network_manager='nova.network.manager.FlatManager') self.compute = utils.import_object(FLAGS.compute_manager) - self.compute_api = compute_api.ComputeAPI() + self.compute_api = compute.API() self.manager = manager.AuthManager() self.user = self.manager.create_user('fake', 'fake', 'fake') self.project = self.manager.create_project('fake', 'fake', 'fake') @@ -72,7 +72,7 @@ class ComputeTestCase(test.TestCase): """Verify that an instance cannot be created without a display_name.""" cases = [dict(), dict(display_name=None)] for instance in cases: - ref = self.compute_api.create_instances(self.context, + ref = self.compute_api.create(self.context, FLAGS.default_instance_type, None, **instance) try: self.assertNotEqual(ref[0].display_name, None) @@ -80,13 +80,13 @@ class ComputeTestCase(test.TestCase): db.instance_destroy(self.context, ref[0]['id']) def test_create_instance_associates_security_groups(self): - """Make sure create_instances associates security groups""" + """Make sure create associates security groups""" values = {'name': 'default', 'description': 'default', 'user_id': self.user.id, 'project_id': self.project.id} group = db.security_group_create(self.context, values) - ref = self.compute_api.create_instances(self.context, + ref = self.compute_api.create(self.context, FLAGS.default_instance_type, None, security_group=['default']) try: self.assertEqual(len(ref[0]['security_groups']), 1) From 19bc02d3d2f291f53626fbef67b7ecbbc62ded48 Mon Sep 17 00:00:00 2001 From: Devin Carlen Date: Thu, 30 Dec 2010 17:50:32 -0800 Subject: [PATCH 10/26] Removed dependencies on flags.py from adminclient --- nova/adminclient.py | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/nova/adminclient.py b/nova/adminclient.py index 6ae9f0c0..b2609c8c 100644 --- a/nova/adminclient.py +++ b/nova/adminclient.py @@ -23,12 +23,9 @@ import base64 import boto import httplib -from nova import flags from boto.ec2.regioninfo import RegionInfo -FLAGS = flags.FLAGS - DEFAULT_CLC_URL = 'http://127.0.0.1:8773' DEFAULT_REGION = 'nova' @@ -199,8 +196,8 @@ class NovaAdminClient(object): self, clc_url=DEFAULT_CLC_URL, region=DEFAULT_REGION, - access_key=FLAGS.aws_access_key_id, - secret_key=FLAGS.aws_secret_access_key, + access_key=None, + secret_key=None, **kwargs): parts = self.split_clc_url(clc_url) From 0799e9ac687e5e6c33aa7c2de3fba6059c65b9da Mon Sep 17 00:00:00 2001 From: Todd Willey Date: Tue, 4 Jan 2011 00:23:35 -0500 Subject: [PATCH 11/26] Apply logging changes as a giant patch to work around the cloudpipe delete + add issue in the original patch. --- bin/nova-dhcpbridge | 20 ++- bin/nova-instancemonitor | 7 +- bin/nova-logspool | 156 +++++++++++++++++ bin/nova-manage | 19 ++- bin/nova-spoolsentry | 97 +++++++++++ nova/auth/ldapdriver.py | 7 +- nova/auth/manager.py | 62 +++++-- nova/auth/signer.py | 15 +- nova/fakerabbit.py | 20 ++- nova/flags.py | 12 +- nova/log.py | 261 +++++++++++++++++++++++++++++ nova/rpc.py | 26 ++- nova/tests/objectstore_unittest.py | 2 - nova/tests/test_access.py | 1 - nova/tests/test_auth.py | 9 +- nova/tests/test_cloud.py | 18 +- nova/tests/test_compute.py | 8 +- nova/tests/test_log.py | 107 ++++++++++++ nova/tests/test_network.py | 9 +- nova/tests/test_rpc.py | 7 +- nova/tests/test_volume.py | 6 +- nova/twistd.py | 25 +-- 22 files changed, 779 insertions(+), 115 deletions(-) create mode 100644 bin/nova-logspool create mode 100644 bin/nova-spoolsentry create mode 100644 nova/log.py create mode 100644 nova/tests/test_log.py diff --git a/bin/nova-dhcpbridge b/bin/nova-dhcpbridge index 828aba3d..cecc1c80 100755 --- a/bin/nova-dhcpbridge +++ b/bin/nova-dhcpbridge @@ -22,7 +22,6 @@ Handle lease database updates from DHCP servers. """ import gettext -import logging import os import sys @@ -39,6 +38,7 @@ gettext.install('nova', unicode=1) from nova import context from nova import db from nova import flags +from nova import log as logging from nova import rpc from nova import utils from nova.network import linux_net @@ -50,10 +50,15 @@ flags.DECLARE('num_networks', 'nova.network.manager') flags.DECLARE('update_dhcp_on_disassociate', 'nova.network.manager') +LOG = logging.getLogger('nova-dhcpbridge') +if FLAGS.verbose: + LOG.setLevel(logging.DEBUG) + + def add_lease(mac, ip_address, _hostname, _interface): """Set the IP that was assigned by the DHCP server.""" if FLAGS.fake_rabbit: - logging.debug("leasing ip") + LOG.debug("leasing ip") network_manager = utils.import_object(FLAGS.network_manager) network_manager.lease_fixed_ip(context.get_admin_context(), mac, @@ -68,14 +73,14 @@ def add_lease(mac, ip_address, _hostname, _interface): def old_lease(mac, ip_address, hostname, interface): """Update just as add lease.""" - logging.debug("Adopted old lease or got a change of mac/hostname") + LOG.debug("Adopted old lease or got a change of mac/hostname") add_lease(mac, ip_address, hostname, interface) def del_lease(mac, ip_address, _hostname, _interface): """Called when a lease expires.""" if FLAGS.fake_rabbit: - logging.debug("releasing ip") + LOG.debug("releasing ip") network_manager = utils.import_object(FLAGS.network_manager) network_manager.release_fixed_ip(context.get_admin_context(), mac, @@ -100,6 +105,7 @@ def main(): flagfile = os.environ.get('FLAGFILE', FLAGS.dhcpbridge_flagfile) utils.default_flagfile(flagfile) argv = FLAGS(sys.argv) + logging.basicConfig() interface = os.environ.get('DNSMASQ_INTERFACE', 'br0') if int(os.environ.get('TESTING', '0')): FLAGS.fake_rabbit = True @@ -117,9 +123,9 @@ def main(): mac = argv[2] ip = argv[3] hostname = argv[4] - logging.debug("Called %s for mac %s with ip %s and " - "hostname %s on interface %s", - action, mac, ip, hostname, interface) + LOG.debug("Called %s for mac %s with ip %s and " + "hostname %s on interface %s", + action, mac, ip, hostname, interface) globals()[action + '_lease'](mac, ip, hostname, interface) else: print init_leases(interface) diff --git a/bin/nova-instancemonitor b/bin/nova-instancemonitor index 5dac3ffe..17f573b9 100755 --- a/bin/nova-instancemonitor +++ b/bin/nova-instancemonitor @@ -23,7 +23,6 @@ import gettext import os -import logging import sys from twisted.application import service @@ -37,19 +36,23 @@ if os.path.exists(os.path.join(possible_topdir, 'nova', '__init__.py')): gettext.install('nova', unicode=1) +from nova import log as logging from nova import utils 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') + if __name__ == '__main__': utils.default_flagfile() twistd.serve(__file__) if __name__ == '__builtin__': - logging.warn('Starting instance monitor') + LOG.warn(_('Starting instance monitor')) # pylint: disable-msg=C0103 monitor = monitor.InstanceMonitor() diff --git a/bin/nova-logspool b/bin/nova-logspool new file mode 100644 index 00000000..d5aef475 --- /dev/null +++ b/bin/nova-logspool @@ -0,0 +1,156 @@ +#!/usr/bin/env python + +# Copyright 2010 United States Government as represented by the +# Administrator of the National Aeronautics and Space Administration. +# All Rights Reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +""" +Tools for working with logs generated by nova components +""" + + +import json +import os +import re +import sys + + +class Request(object): + + def __init__(self): + self.time = "" + self.host = "" + self.logger = "" + self.message = "" + self.trace = "" + self.env = "" + self.request_id = "" + + def add_error_line(self, error_line): + self.time = " ".join(error_line.split(" ")[:3]) + self.host = error_line.split(" ")[3] + self.logger = error_line.split("(")[1].split(" ")[0] + self.request_id = error_line.split("[")[1].split(" ")[0] + error_lines = error_line.split("#012") + self.message = self.clean_log_line(error_lines.pop(0)) + self.trace = "\n".join([self.clean_trace(l) for l in error_lines]) + + def add_environment_line(self, env_line): + self.env = self.clean_env_line(env_line) + + def clean_log_line(self, line): + """Remove log format for time, level, etc: split after context""" + return line.split('] ')[-1] + + def clean_env_line(self, line): + """Also has an 'Environment: ' string in the message""" + return re.sub(r'^Environment: ', '', self.clean_log_line(line)) + + def clean_trace(self, line): + """trace has a different format, so split on TRACE:""" + return line.split('TRACE: ')[-1] + + def to_dict(self): + return {'traceback': self.trace, 'message': self.message, + 'host': self.host, 'env': self.env, 'logger': self.logger, + 'request_id': self.request_id} + +class LogReader(object): + def __init__(self, filename): + self.filename = filename + self._errors = {} + + def process(self, spooldir): + with open(self.filename) as f: + line = f.readline() + while len(line) > 0: + parts = line.split(" ") + level = (len(parts) < 6) or parts[5] + if level == 'ERROR': + self.handle_logged_error(line) + elif level == '[-]' and self.last_error: + # twisted stack trace line + clean_line = " ".join(line.split(" ")[6:]) + self.last_error.trace = self.last_error.trace + clean_line + else: + self.last_error = None + line = f.readline() + self.update_spool(spooldir) + + def handle_logged_error(self, line): + request_id = re.search(r' \[([A-Z0-9\-/]+)', line) + if not request_id: + raise Exception("Unable to parse request id from %s" % line) + request_id = request_id.group(1) + data = self._errors.get(request_id, Request()) + if self.is_env_line(line): + data.add_environment_line(line) + elif self.is_error_line(line): + data.add_error_line(line) + else: + # possibly error from twsited + data.add_error_line(line) + self.last_error = data + self._errors[request_id] = data + + def is_env_line(self, line): + return re.search('Environment: ', line) + + def is_error_line(self, line): + return re.search('raised', line) + + def update_spool(self, directory): + processed_dir = "%s/processed" % directory + self._ensure_dir_exists(processed_dir) + for rid, value in self._errors.iteritems(): + if not self.has_been_processed(processed_dir, rid): + with open("%s/%s" % (directory, rid), "w") as spool: + spool.write(json.dumps(value.to_dict())) + self.flush_old_processed_spool(processed_dir) + + def _ensure_dir_exists(self, d): + mkdir = False + try: + os.stat(d) + except: + mkdir = True + if mkdir: + os.mkdir(d) + + def has_been_processed(self, processed_dir, rid): + rv = False + try: + os.stat("%s/%s" % (processed_dir, rid)) + rv = True + except: + pass + return rv + + def flush_old_processed_spool(self, processed_dir): + keys = self._errors.keys() + procs = os.listdir(processed_dir) + for p in procs: + if p not in keys: + # log has rotated and the old error won't be seen again + os.unlink("%s/%s" % (processed_dir, p)) + +if __name__ == '__main__': + filename = '/var/log/nova.log' + spooldir = '/var/spool/nova' + if len(sys.argv) > 1: + filename = sys.argv[1] + if len(sys.argv) > 2: + spooldir = sys.argv[2] + LogReader(filename).process(spooldir) diff --git a/bin/nova-manage b/bin/nova-manage index 3416c1a5..169ab5f6 100755 --- a/bin/nova-manage +++ b/bin/nova-manage @@ -55,8 +55,8 @@ import datetime import gettext -import logging import os +import re import sys import time @@ -77,6 +77,7 @@ from nova import crypto from nova import db from nova import exception from nova import flags +from nova import log as logging from nova import quota from nova import utils from nova.auth import manager @@ -499,6 +500,15 @@ class ServiceCommands(object): db.service_update(ctxt, svc['id'], {'disabled': True}) +class LogCommands(object): + def request(self, request_id, logfile='/var/log/nova.log'): + """Show all fields in the log for the given request. Assumes you + haven't changed the log format too much. + ARGS: request_id [logfile]""" + lines = utils.execute("cat %s | grep '\[%s '" % (logfile, request_id)) + print re.sub('#012', "\n", "\n".join(lines)) + + CATEGORIES = [ ('user', UserCommands), ('project', ProjectCommands), @@ -507,7 +517,8 @@ CATEGORIES = [ ('vpn', VpnCommands), ('floating', FloatingIpCommands), ('network', NetworkCommands), - ('service', ServiceCommands)] + ('service', ServiceCommands), + ('log', LogCommands)] def lazy_match(name, key_value_tuples): @@ -546,9 +557,7 @@ def main(): utils.default_flagfile() argv = FLAGS(sys.argv) - if FLAGS.verbose: - logging.getLogger().setLevel(logging.DEBUG) - + logging._set_log_levels() script_name = argv.pop(0) if len(argv) < 1: print script_name + " category action []" diff --git a/bin/nova-spoolsentry b/bin/nova-spoolsentry new file mode 100644 index 00000000..ab20268a --- /dev/null +++ b/bin/nova-spoolsentry @@ -0,0 +1,97 @@ +#!/usr/bin/env python +# vim: tabstop=4 shiftwidth=4 softtabstop=4 + +# Copyright 2010 United States Government as represented by the +# Administrator of the National Aeronautics and Space Administration. +# All Rights Reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. + + +import base64 +import json +import logging +import os +import shutil +import sys +import urllib +import urllib2 +try: + import cPickle as pickle +except: + import pickle + + +class SpoolSentry(object): + def __init__(self, spool_dir, sentry_url, key=None): + self.spool_dir = spool_dir + self.sentry_url = sentry_url + self.key = key + + def process(self): + for fname in os.listdir(self.spool_dir): + if fname == "processed": + continue + try: + sourcefile = "%s/%s" % (self.spool_dir, fname) + with open(sourcefile) as f: + fdata = f.read() + data_from_json = json.loads(fdata) + data = self.build_data(data_from_json) + self.send_data(data) + destfile = "%s/processed/%s" % (self.spool_dir, fname) + shutil.move(sourcefile, destfile) + except: + logging.exception("Unable to upload record %s", fname) + raise + + def build_data(self, filejson): + env = {'SERVER_NAME': 'unknown', 'SERVER_PORT': '0000', + 'SCRIPT_NAME': '/unknown/', 'PATH_INFO': 'unknown'} + if filejson['env']: + env = json.loads(filejson['env']) + url = "http://%s:%s%s%s" % (env['SERVER_NAME'], env['SERVER_PORT'], + env['SCRIPT_NAME'], env['PATH_INFO']) + rv = {'logger': filejson['logger'], 'level': logging.ERROR, + 'server_name': filejson['host'], 'url': url, + 'message': filejson['message'], + 'traceback': filejson['traceback']} + rv['data'] = {} + if filejson['env']: + rv['data']['META'] = env + if filejson['request_id']: + rv['data']['request_id'] = filejson['request_id'] + return rv + + def send_data(self, data): + data = { + 'data': base64.b64encode(pickle.dumps(data).encode('zlib')), + 'key': self.key + } + req = urllib2.Request(self.sentry_url) + res = urllib2.urlopen(req, urllib.urlencode(data)) + if res.getcode() != 200: + raise Exception("Bad HTTP code: %s" % res.getcode()) + txt = res.read() + +if __name__ == '__main__': + sentryurl = 'http://127.0.0.1/sentry/store/' + key = '' + spooldir = '/var/spool/nova' + if len(sys.argv) > 1: + sentryurl = sys.argv[1] + if len(sys.argv) > 2: + key = sys.argv[2] + if len(sys.argv) > 3: + spooldir = sys.argv[3] + SpoolSentry(spooldir, sentryurl, key).process() diff --git a/nova/auth/ldapdriver.py b/nova/auth/ldapdriver.py index 7616ff11..3e0837ba 100644 --- a/nova/auth/ldapdriver.py +++ b/nova/auth/ldapdriver.py @@ -24,11 +24,11 @@ other backends by creating another class that exposes the same public methods. """ -import logging import sys from nova import exception from nova import flags +from nova import log as logging FLAGS = flags.FLAGS @@ -66,6 +66,9 @@ flags.DEFINE_string('ldap_developer', 'cn=developers,ou=Groups,dc=example,dc=com', 'cn for Developers') +LOG = logging.getLogger("nova.ldapdriver") + + # TODO(vish): make an abstract base class with the same public methods # to define a set interface for AuthDrivers. I'm delaying # creating this now because I'm expecting an auth refactor @@ -502,7 +505,7 @@ class LdapDriver(object): try: self.conn.modify_s(group_dn, attr) except self.ldap.OBJECT_CLASS_VIOLATION: - logging.debug(_("Attempted to remove the last member of a group. " + LOG.debug(_("Attempted to remove the last member of a group. " "Deleting the group at %s instead."), group_dn) self.__delete_group(group_dn) diff --git a/nova/auth/manager.py b/nova/auth/manager.py index d3e26695..bfac7fc2 100644 --- a/nova/auth/manager.py +++ b/nova/auth/manager.py @@ -20,7 +20,6 @@ Nova authentication management """ -import logging import os import shutil import string # pylint: disable-msg=W0402 @@ -33,6 +32,7 @@ from nova import crypto from nova import db from nova import exception from nova import flags +from nova import log as logging from nova import utils from nova.auth import signer @@ -71,6 +71,9 @@ flags.DEFINE_string('auth_driver', 'nova.auth.dbdriver.DbDriver', 'Driver that auth manager uses') +LOG = logging.getLogger('nova.authmanager') + + class AuthBase(object): """Base class for objects relating to auth @@ -254,43 +257,51 @@ class AuthManager(object): # TODO(vish): check for valid timestamp (access_key, _sep, project_id) = access.partition(':') - logging.info(_('Looking up user: %r'), access_key) + LOG.debug(_('Looking up user: %r'), access_key) user = self.get_user_from_access_key(access_key) - logging.info('user: %r', user) + LOG.debug('user: %r', user) if user == None: + LOG.audit(_("Failed authorization for access key %s"), access_key) raise exception.NotFound(_('No user found for access key %s') % access_key) # NOTE(vish): if we stop using project name as id we need better # logic to find a default project for user if project_id == '': + LOG.debug(_("Using project name = user name (%s)"), user.name) project_id = user.name project = self.get_project(project_id) if project == None: + LOG.audit(_("failed authorization: no project named %s (user=%s)"), + project_id, user.name) raise exception.NotFound(_('No project called %s could be found') % project_id) if not self.is_admin(user) and not self.is_project_member(user, project): + LOG.audit(_("Failed authorization: user %s not admin and not " + "member of project %s"), user.name, project.name) raise exception.NotFound(_('User %s is not a member of project %s') % (user.id, project.id)) if check_type == 's3': sign = signer.Signer(user.secret.encode()) expected_signature = sign.s3_authorization(headers, verb, path) - logging.debug('user.secret: %s', user.secret) - logging.debug('expected_signature: %s', expected_signature) - logging.debug('signature: %s', signature) + LOG.debug('user.secret: %s', user.secret) + LOG.debug('expected_signature: %s', expected_signature) + LOG.debug('signature: %s', signature) if signature != expected_signature: + LOG.audit(_("Invalid signature for user %s"), user.name) raise exception.NotAuthorized(_('Signature does not match')) elif check_type == 'ec2': # NOTE(vish): hmac can't handle unicode, so encode ensures that # secret isn't unicode expected_signature = signer.Signer(user.secret.encode()).generate( params, verb, server_string, path) - logging.debug('user.secret: %s', user.secret) - logging.debug('expected_signature: %s', expected_signature) - logging.debug('signature: %s', signature) + LOG.debug('user.secret: %s', user.secret) + LOG.debug('expected_signature: %s', expected_signature) + LOG.debug('signature: %s', signature) if signature != expected_signature: + LOG.audit(_("Invalid signature for user %s"), user.name) raise exception.NotAuthorized(_('Signature does not match')) return (user, project) @@ -398,6 +409,12 @@ class AuthManager(object): raise exception.NotFound(_("The %s role can not be found") % role) if project is not None and role in FLAGS.global_roles: raise exception.NotFound(_("The %s role is global only") % role) + if project: + LOG.audit(_("Adding role %s to user %s in project %s"), role, + User.safe_id(user), Project.safe_id(project)) + else: + LOG.audit(_("Adding sitewide role %s to user %s"), role, + User.safe_id(user)) with self.driver() as drv: drv.add_role(User.safe_id(user), role, Project.safe_id(project)) @@ -418,6 +435,12 @@ class AuthManager(object): @type project: Project or project_id @param project: Project in which to remove local role. """ + if project: + LOG.audit(_("Removing role %s from user %s on project %s"), + role, User.safe_id(user), Project.safe_id(project)) + else: + LOG.audit(_("Removing sitewide role %s from user %s"), role, + User.safe_id(user)) with self.driver() as drv: drv.remove_role(User.safe_id(user), role, Project.safe_id(project)) @@ -480,6 +503,8 @@ class AuthManager(object): description, member_users) if project_dict: + LOG.audit(_("Created project %s with manager %s"), name, + manager_user) project = Project(**project_dict) return project @@ -496,6 +521,7 @@ class AuthManager(object): @param project: This will be the new description of the project. """ + LOG.audit(_("modifying project %s"), Project.safe_id(project)) if manager_user: manager_user = User.safe_id(manager_user) with self.driver() as drv: @@ -505,6 +531,8 @@ class AuthManager(object): def add_to_project(self, user, project): """Add user to project""" + LOG.audit(_("Adding user %s to project %s"), User.safe_id(user), + Project.safe_id(project)) with self.driver() as drv: return drv.add_to_project(User.safe_id(user), Project.safe_id(project)) @@ -523,6 +551,8 @@ class AuthManager(object): def remove_from_project(self, user, project): """Removes a user from a project""" + LOG.audit(_("Remove user %s from project %s"), User.safe_id(user), + Project.safe_id(project)) with self.driver() as drv: return drv.remove_from_project(User.safe_id(user), Project.safe_id(project)) @@ -549,6 +579,7 @@ class AuthManager(object): def delete_project(self, project): """Deletes a project""" + LOG.audit(_("Deleting project %s"), Project.safe_id(project)) with self.driver() as drv: drv.delete_project(Project.safe_id(project)) @@ -603,13 +634,16 @@ class AuthManager(object): with self.driver() as drv: user_dict = drv.create_user(name, access, secret, admin) if user_dict: - return User(**user_dict) + rv = User(**user_dict) + LOG.audit(_("Created user %s (admin: %r)"), rv.name, rv.admin) + return rv def delete_user(self, user): """Deletes a user Additionally deletes all users key_pairs""" uid = User.safe_id(user) + LOG.audit(_("Deleting user %s"), uid) db.key_pair_destroy_all_by_user(context.get_admin_context(), uid) with self.driver() as drv: @@ -618,6 +652,12 @@ class AuthManager(object): def modify_user(self, user, access_key=None, secret_key=None, admin=None): """Modify credentials for a user""" uid = User.safe_id(user) + if access_key: + LOG.audit(_("Access Key change for user %s"), uid) + if secret_key: + LOG.audit(_("Secret Key change for user %s"), uid) + if admin is not None: + LOG.audit(_("Admin status set to %r for user %s"), admin, uid) with self.driver() as drv: drv.modify_user(uid, access_key, secret_key, admin) @@ -666,7 +706,7 @@ class AuthManager(object): port=vpn_port) zippy.writestr(FLAGS.credential_vpn_file, config) else: - logging.warn(_("No vpn data for project %s"), pid) + LOG.warn(_("No vpn data for project %s"), pid) zippy.writestr(FLAGS.ca_file, crypto.fetch_ca(pid)) zippy.close() diff --git a/nova/auth/signer.py b/nova/auth/signer.py index f7d29f53..744e315d 100644 --- a/nova/auth/signer.py +++ b/nova/auth/signer.py @@ -46,7 +46,6 @@ Utility class for parsing signed AMI manifests. import base64 import hashlib import hmac -import logging import urllib # NOTE(vish): for new boto @@ -54,9 +53,13 @@ import boto # NOTE(vish): for old boto import boto.utils +from nova import log as logging from nova.exception import Error +LOG = logging.getLogger('nova.signer') + + class Signer(object): """Hacked up code from boto/connection.py""" @@ -120,7 +123,7 @@ class Signer(object): def _calc_signature_2(self, params, verb, server_string, path): """Generate AWS signature version 2 string.""" - logging.debug('using _calc_signature_2') + LOG.debug('using _calc_signature_2') string_to_sign = '%s\n%s\n%s\n' % (verb, server_string, path) if self.hmac_256: current_hmac = self.hmac_256 @@ -136,13 +139,13 @@ class Signer(object): val = urllib.quote(val, safe='-_~') pairs.append(urllib.quote(key, safe='') + '=' + val) qs = '&'.join(pairs) - logging.debug('query string: %s', qs) + LOG.debug('query string: %s', qs) string_to_sign += qs - logging.debug('string_to_sign: %s', string_to_sign) + LOG.debug('string_to_sign: %s', string_to_sign) current_hmac.update(string_to_sign) b64 = base64.b64encode(current_hmac.digest()) - logging.debug('len(b64)=%d', len(b64)) - logging.debug('base64 encoded digest: %s', b64) + LOG.debug('len(b64)=%d', len(b64)) + LOG.debug('base64 encoded digest: %s', b64) return b64 diff --git a/nova/fakerabbit.py b/nova/fakerabbit.py index 79d8b894..7c2d7177 100644 --- a/nova/fakerabbit.py +++ b/nova/fakerabbit.py @@ -18,12 +18,16 @@ """Based a bit on the carrot.backeds.queue backend... but a lot better.""" -import logging import Queue as queue from carrot.backends import base from eventlet import greenthread +from nova import log as logging + + +LOG = logging.getLogger("nova.fakerabbit") + EXCHANGES = {} QUEUES = {} @@ -41,12 +45,12 @@ class Exchange(object): self._routes = {} def publish(self, message, routing_key=None): - logging.debug(_('(%s) publish (key: %s) %s'), - self.name, routing_key, message) + LOG.debug(_('(%s) publish (key: %s) %s'), + self.name, routing_key, message) routing_key = routing_key.split('.')[0] if routing_key in self._routes: for f in self._routes[routing_key]: - logging.debug(_('Publishing to route %s'), f) + LOG.debug(_('Publishing to route %s'), f) f(message, routing_key=routing_key) def bind(self, callback, routing_key): @@ -76,19 +80,19 @@ class Backend(base.BaseBackend): def queue_declare(self, queue, **kwargs): global QUEUES if queue not in QUEUES: - logging.debug(_('Declaring queue %s'), queue) + LOG.debug(_('Declaring queue %s'), queue) QUEUES[queue] = Queue(queue) def exchange_declare(self, exchange, type, *args, **kwargs): global EXCHANGES if exchange not in EXCHANGES: - logging.debug(_('Declaring exchange %s'), exchange) + LOG.debug(_('Declaring exchange %s'), exchange) EXCHANGES[exchange] = Exchange(exchange, type) def queue_bind(self, queue, exchange, routing_key, **kwargs): global EXCHANGES global QUEUES - logging.debug(_('Binding %s to %s with key %s'), + LOG.debug(_('Binding %s to %s with key %s'), queue, exchange, routing_key) EXCHANGES[exchange].bind(QUEUES[queue].push, routing_key) @@ -113,7 +117,7 @@ class Backend(base.BaseBackend): content_type=content_type, content_encoding=content_encoding) message.result = True - logging.debug(_('Getting from %s: %s'), queue, message) + LOG.debug(_('Getting from %s: %s'), queue, message) return message def prepare_message(self, message_data, delivery_mode, diff --git a/nova/flags.py b/nova/flags.py index 4b733492..f5c2d423 100644 --- a/nova/flags.py +++ b/nova/flags.py @@ -29,8 +29,6 @@ import sys import gflags -from nova import utils - class FlagValues(gflags.FlagValues): """Extension of gflags.FlagValues that allows undefined and runtime flags. @@ -213,10 +211,10 @@ DEFINE_string('connection_type', 'libvirt', 'libvirt, xenapi or fake') DEFINE_string('aws_access_key_id', 'admin', 'AWS Access ID') DEFINE_string('aws_secret_access_key', 'admin', 'AWS Access Key') DEFINE_integer('glance_port', 9292, 'glance port') -DEFINE_string('glance_host', utils.get_my_ip(), 'glance host') +DEFINE_string('glance_host', '127.0.0.1', 'glance host') DEFINE_integer('s3_port', 3333, 's3 port') -DEFINE_string('s3_host', utils.get_my_ip(), 's3 host (for infrastructure)') -DEFINE_string('s3_dmz', utils.get_my_ip(), 's3 dmz ip (for instances)') +DEFINE_string('s3_host', '127.0.0.1', 's3 host (for infrastructure)') +DEFINE_string('s3_dmz', '127.0.0.1', 's3 dmz ip (for instances)') DEFINE_string('compute_topic', 'compute', 'the topic compute nodes listen on') DEFINE_string('scheduler_topic', 'scheduler', 'the topic scheduler nodes listen on') @@ -236,8 +234,8 @@ DEFINE_integer('rabbit_retry_interval', 10, 'rabbit connection retry interval') DEFINE_integer('rabbit_max_retries', 12, 'rabbit connection attempts') DEFINE_string('control_exchange', 'nova', 'the main exchange to connect to') DEFINE_string('ec2_prefix', 'http', 'prefix for ec2') -DEFINE_string('cc_host', utils.get_my_ip(), 'ip of api server') -DEFINE_string('cc_dmz', utils.get_my_ip(), 'internal ip of api server') +DEFINE_string('cc_host', '127.0.0.1', 'ip of api server') +DEFINE_string('cc_dmz', '127.0.0.1', 'internal ip of api server') DEFINE_integer('cc_port', 8773, 'cloud controller port') DEFINE_string('ec2_suffix', '/services/Cloud', 'suffix for ec2') diff --git a/nova/log.py b/nova/log.py new file mode 100644 index 00000000..88a961e1 --- /dev/null +++ b/nova/log.py @@ -0,0 +1,261 @@ +# vim: tabstop=4 shiftwidth=4 softtabstop=4 + +# Copyright 2010 United States Government as represented by the +# Administrator of the National Aeronautics and Space Administration. +# All Rights Reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. + +""" +Nova logging handler. + +This module adds to logging functionality by adding the option to specify +a context object when calling the various log methods. If the context object +is not specified, default formatting is used. + +It also allows setting of formatting information through flags. +""" + + +import cStringIO +import json +import logging +import logging.handlers +import traceback + +from nova import flags +# TODO(todd): fix after version.py merge +# from nova import version + + +FLAGS = flags.FLAGS + +# TODO(todd): fix after version.py merge +# '(%(name)s %(nova_version)s): %(levelname)s ' +flags.DEFINE_string('logging_context_format_string', + '(%(name)s): %(levelname)s ' + '[%(request_id)s %(user)s ' + '%(project)s] %(message)s', + 'format string to use for log messages') + +# TODO(todd): fix after version.py merge +# '(%(name)s %(nova_version)s): %(levelname)s [N/A] ' +flags.DEFINE_string('logging_default_format_string', + '(%(name)s): %(levelname)s [N/A] ' + '%(message)s', + 'format string to use for log messages') + +flags.DEFINE_string('logging_debug_format_suffix', + 'from %(processName)s (pid=%(process)d) %(funcName)s' + ' %(pathname)s:%(lineno)d', + 'data to append to log format when level is DEBUG') + +flags.DEFINE_string('logging_exception_prefix', + '(%(name)s): TRACE: ', + 'prefix each line of exception output with this format') + +flags.DEFINE_list('default_log_levels', + ['amqplib=WARN', + 'sqlalchemy=WARN', + 'audit=INFO'], + 'list of logger=LEVEL pairs') + +flags.DEFINE_bool('use_syslog', False, 'output to syslog') +flags.DEFINE_string('logfile', None, 'output to named file') + + + +# A list of things we want to replicate from logging. +# levels +CRITICAL = logging.CRITICAL +FATAL = logging.FATAL +ERROR = logging.ERROR +WARNING = logging.WARNING +WARN = logging.WARN +INFO = logging.INFO +DEBUG = logging.DEBUG +NOTSET = logging.NOTSET +# methods +getLogger = logging.getLogger +debug = logging.debug +info = logging.info +warning = logging.warning +warn = logging.warn +error = logging.error +exception = logging.exception +critical = logging.critical +log = logging.log +# handlers +StreamHandler = logging.StreamHandler +FileHandler = logging.FileHandler +# logging.SysLogHandler is nicer than logging.logging.handler.SysLogHandler. +SysLogHandler = logging.handlers.SysLogHandler + + +# our new audit level +AUDIT = logging.INFO + 1 +logging.addLevelName(AUDIT, 'AUDIT') + + +def _dictify_context(context): + if context == None: + return None + if not isinstance(context, dict) \ + and getattr(context, 'to_dict', None): + context = context.to_dict() + return context + + +def basicConfig(): + logging.basicConfig() + for handler in logging.root.handlers: + handler.setFormatter(_formatter) + if FLAGS.verbose: + logging.root.setLevel(logging.DEBUG) + if FLAGS.use_syslog: + syslog = SysLogHandler(address='/dev/log') + syslog.setFormatter(_formatter) + logging.root.addHandler(syslog) + if FLAGS.logfile: + logfile = FileHandler(FLAGS.logfile) + 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' + 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 _log(self, level, msg, args, exc_info=None, extra=None, context=None): + """Extract context from any log call""" + if not extra: + extra = {} + if context: + extra.update(_dictify_context(context)) + # TODO(todd): fix after version.py merge + #extra.update({"nova_version": version.string_with_vcs()}) + 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) + + def audit(self, msg, *args, **kwargs): + """Shortcut for our AUDIT level""" + if self.isEnabledFor(AUDIT): + self._log(AUDIT, msg, args, **kwargs) + + def exception(self, msg, *args, **kwargs): + """Logging.exception doesn't handle kwargs, so breaks context""" + if not kwargs.get('exc_info'): + kwargs['exc_info'] = 1 + self.error(msg, *args, **kwargs) + # NOTE(todd): does this really go here, or in _log ? + extra = kwargs.get('extra') + if not extra: + return + env = extra.get('environment') + if env: + env = env.copy() + for k in env.keys(): + if not isinstance(env[k], str): + env.pop(k) + message = "Environment: %s" % json.dumps(env) + kwargs.pop('exc_info') + self.error(message, **kwargs) + +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. + + The flags used to set format strings are: logging_context_foramt_string + and logging_default_format_string. You can also specify + logging_debug_format_suffix to append extra formatting if the log level is + debug. + + For information about what variables are available for the formatter see: + http://docs.python.org/library/logging.html#formatter + """ + + def format(self, record): + """Uses contextstring if request_id is set, otherwise default""" + if record.__dict__.get('request_id', None): + self._fmt = FLAGS.logging_context_format_string + else: + self._fmt = FLAGS.logging_default_format_string + if record.levelno == logging.DEBUG \ + and FLAGS.logging_debug_format_suffix: + self._fmt += " " + FLAGS.logging_debug_format_suffix + # Cache this on the record, Logger will respect our formated copy + if record.exc_info: + record.exc_text = self.formatException(record.exc_info, record) + return logging.Formatter.format(self, record) + + def formatException(self, exc_info, record=None): + """Format exception output with FLAGS.logging_exception_prefix""" + if not record: + return logging.Formatter.formatException(self, exc_info) + stringbuffer = cStringIO.StringIO() + traceback.print_exception(exc_info[0], exc_info[1], exc_info[2], + None, stringbuffer) + lines = stringbuffer.getvalue().split("\n") + stringbuffer.close() + formatted_lines = [] + for line in lines: + pl = FLAGS.logging_exception_prefix % record.__dict__ + fl = "%s%s" % (pl, line) + formatted_lines.append(fl) + return "\n".join(formatted_lines) + +_formatter = NovaFormatter() + + +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) diff --git a/nova/rpc.py b/nova/rpc.py index 84408834..02052485 100644 --- a/nova/rpc.py +++ b/nova/rpc.py @@ -22,7 +22,6 @@ No fan-out support yet. """ import json -import logging import sys import time import traceback @@ -36,13 +35,12 @@ from nova import context from nova import exception from nova import fakerabbit from nova import flags +from nova import log as logging from nova import utils FLAGS = flags.FLAGS - -LOG = logging.getLogger('amqplib') -LOG.setLevel(logging.DEBUG) +LOG = logging.getLogger('nova.rpc') class Connection(carrot_connection.BrokerConnection): @@ -91,14 +89,14 @@ class Consumer(messaging.Consumer): self.failed_connection = False break except: # Catching all because carrot sucks - logging.exception(_("AMQP server on %s:%d is unreachable." - " Trying again in %d seconds.") % ( - FLAGS.rabbit_host, - FLAGS.rabbit_port, - FLAGS.rabbit_retry_interval)) + LOG.exception(_("AMQP server on %s:%d is unreachable." + " Trying again in %d seconds.") % ( + FLAGS.rabbit_host, + FLAGS.rabbit_port, + FLAGS.rabbit_retry_interval)) self.failed_connection = True if self.failed_connection: - logging.exception(_("Unable to connect to AMQP server" + LOG.exception(_("Unable to connect to AMQP server" " after %d tries. Shutting down.") % FLAGS.rabbit_max_retries) sys.exit(1) @@ -116,14 +114,14 @@ class Consumer(messaging.Consumer): self.declare() super(Consumer, self).fetch(no_ack, auto_ack, enable_callbacks) if self.failed_connection: - logging.error(_("Reconnected to queue")) + LOG.error(_("Reconnected to queue")) self.failed_connection = False # NOTE(vish): This is catching all errors because we really don't # exceptions to be logged 10 times a second if some # persistent failure occurs. except Exception: # pylint: disable-msg=W0703 if not self.failed_connection: - logging.exception(_("Failed to fetch message from queue")) + LOG.exception(_("Failed to fetch message from queue")) self.failed_connection = True def attach_to_eventlet(self): @@ -242,8 +240,8 @@ def msg_reply(msg_id, reply=None, failure=None): if failure: message = str(failure[1]) tb = traceback.format_exception(*failure) - logging.error(_("Returning exception %s to caller"), message) - logging.error(tb) + LOG.error(_("Returning exception %s to caller"), message) + LOG.error(tb) failure = (failure[0].__name__, str(failure[1]), tb) conn = Connection.instance(True) publisher = DirectPublisher(connection=conn, msg_id=msg_id) diff --git a/nova/tests/objectstore_unittest.py b/nova/tests/objectstore_unittest.py index ceac17ad..da86e6e1 100644 --- a/nova/tests/objectstore_unittest.py +++ b/nova/tests/objectstore_unittest.py @@ -23,7 +23,6 @@ Unittets for S3 objectstore clone. import boto import glob import hashlib -import logging import os import shutil import tempfile @@ -63,7 +62,6 @@ class ObjectStoreTestCase(test.TestCase): self.flags(buckets_path=os.path.join(OSS_TEMPDIR, 'buckets'), images_path=os.path.join(OSS_TEMPDIR, 'images'), ca_path=os.path.join(os.path.dirname(__file__), 'CA')) - logging.getLogger().setLevel(logging.DEBUG) self.auth_manager = manager.AuthManager() self.auth_manager.create_user('user1') diff --git a/nova/tests/test_access.py b/nova/tests/test_access.py index 58fdea3b..0929903c 100644 --- a/nova/tests/test_access.py +++ b/nova/tests/test_access.py @@ -17,7 +17,6 @@ # under the License. import unittest -import logging import webob from nova import context diff --git a/nova/tests/test_auth.py b/nova/tests/test_auth.py index 15d40bc5..35ffffb6 100644 --- a/nova/tests/test_auth.py +++ b/nova/tests/test_auth.py @@ -16,17 +16,18 @@ # License for the specific language governing permissions and limitations # under the License. -import logging from M2Crypto import X509 import unittest from nova import crypto from nova import flags +from nova import log as logging from nova import test from nova.auth import manager from nova.api.ec2 import cloud FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.auth_unittest') class user_generator(object): @@ -211,12 +212,12 @@ class AuthManagerTestCase(object): # NOTE(vish): Setup runs genroot.sh if it hasn't been run cloud.CloudController().setup() _key, cert_str = crypto.generate_x509_cert(user.id, project.id) - logging.debug(cert_str) + LOG.debug(cert_str) full_chain = crypto.fetch_ca(project_id=project.id, chain=True) int_cert = crypto.fetch_ca(project_id=project.id, chain=False) cloud_cert = crypto.fetch_ca() - logging.debug("CA chain:\n\n =====\n%s\n\n=====" % full_chain) + LOG.debug("CA chain:\n\n =====\n%s\n\n=====", full_chain) signed_cert = X509.load_cert_string(cert_str) chain_cert = X509.load_cert_string(full_chain) int_cert = X509.load_cert_string(int_cert) @@ -331,7 +332,7 @@ class AuthManagerLdapTestCase(AuthManagerTestCase, test.TestCase): test.TestCase.__init__(self, *args, **kwargs) import nova.auth.fakeldap as fakeldap if FLAGS.flush_db: - logging.info("Flushing datastore") + LOG.info("Flushing datastore") r = fakeldap.Store.instance() r.flushdb() diff --git a/nova/tests/test_cloud.py b/nova/tests/test_cloud.py index 70d2c44d..e6ad2432 100644 --- a/nova/tests/test_cloud.py +++ b/nova/tests/test_cloud.py @@ -18,7 +18,6 @@ from base64 import b64decode import json -import logging from M2Crypto import BIO from M2Crypto import RSA import os @@ -31,6 +30,7 @@ from nova import context from nova import crypto from nova import db from nova import flags +from nova import log as logging from nova import rpc from nova import service from nova import test @@ -41,6 +41,7 @@ from nova.objectstore import image FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.cloud') # Temp dirs for working with image attributes through the cloud controller # (stole this from objectstore_unittest.py) @@ -56,7 +57,6 @@ class CloudTestCase(test.TestCase): images_path=IMAGES_PATH) self.conn = rpc.Connection.instance() - logging.getLogger().setLevel(logging.DEBUG) # set up our cloud self.cloud = cloud.CloudController() @@ -178,7 +178,7 @@ class CloudTestCase(test.TestCase): def test_run_instances(self): if FLAGS.connection_type == 'fake': - logging.debug("Can't test instances without a real virtual env.") + LOG.debug(_("Can't test instances without a real virtual env.")) return image_id = FLAGS.default_image instance_type = FLAGS.default_instance_type @@ -190,25 +190,25 @@ class CloudTestCase(test.TestCase): # TODO: check for proper response instance_id = rv['reservationSet'][0].keys()[0] instance = rv['reservationSet'][0][instance_id][0] - logging.debug("Need to watch instance %s until it's running..." % - instance['instance_id']) + LOG.debug(_("Need to watch instance %s until it's running..."), + instance['instance_id']) while True: greenthread.sleep(1) info = self.cloud._get_instance(instance['instance_id']) - logging.debug(info['state']) + LOG.debug(info['state']) if info['state'] == power_state.RUNNING: break self.assert_(rv) - if connection_type != 'fake': + if FLAGS.connection_type != 'fake': time.sleep(45) # Should use boto for polling here for reservations in rv['reservationSet']: # for res_id in reservations.keys(): - # logging.debug(reservations[res_id]) + # LOG.debug(reservations[res_id]) # for instance in reservations[res_id]: for instance in reservations[reservations.keys()[0]]: instance_id = instance['instance_id'] - logging.debug("Terminating instance %s" % instance_id) + LOG.debug(_("Terminating instance %s"), instance_id) rv = yield self.compute.terminate_instance(instance_id) def test_instance_update_state(self): diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index 1fb9143f..889ffe99 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -20,12 +20,12 @@ Tests For Compute """ import datetime -import logging 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 test from nova import utils from nova.auth import manager @@ -33,12 +33,12 @@ from nova.compute import api as compute_api FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.compute') class ComputeTestCase(test.TestCase): """Test case for compute""" def setUp(self): - logging.getLogger().setLevel(logging.DEBUG) super(ComputeTestCase, self).setUp() self.flags(connection_type='fake', stub_network=True, @@ -101,13 +101,13 @@ class ComputeTestCase(test.TestCase): self.compute.run_instance(self.context, instance_id) instances = db.instance_get_all(context.get_admin_context()) - logging.info(_("Running instances: %s"), instances) + LOG.info(_("Running instances: %s"), instances) self.assertEqual(len(instances), 1) self.compute.terminate_instance(self.context, instance_id) instances = db.instance_get_all(context.get_admin_context()) - logging.info(_("After terminating instances: %s"), instances) + LOG.info(_("After terminating instances: %s"), instances) self.assertEqual(len(instances), 0) def test_run_terminate_timestamps(self): diff --git a/nova/tests/test_log.py b/nova/tests/test_log.py new file mode 100644 index 00000000..d8dd3870 --- /dev/null +++ b/nova/tests/test_log.py @@ -0,0 +1,107 @@ +import cStringIO + +from nova import context +from nova import log +from nova import test + + +def _fake_context(): + return context.RequestContext(1, 1) + + +class RootLoggerTestCase(test.TrialTestCase): + def setUp(self): + 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_handlers_have_nova_formatter(self): + formatters = [] + for h in self.log.handlers: + f = h.formatter + if isinstance(f, log.NovaFormatter): + formatters.append(f) + self.assert_(formatters) + self.assertEqual(len(formatters), len(self.log.handlers)) + + def test_handles_context_kwarg(self): + self.log.info("foo", context=_fake_context()) + self.assert_(True) # didn't raise exception + + def test_module_level_methods_handle_context_arg(self): + log.info("foo", context=_fake_context()) + self.assert_(True) # didn't raise exception + + def test_module_level_audit_handles_context_arg(self): + log.audit("foo", context=_fake_context()) + self.assert_(True) # didn't raise exception + +class NovaFormatterTestCase(test.TrialTestCase): + def setUp(self): + super(NovaFormatterTestCase, self).setUp() + self.flags(logging_context_format_string="HAS CONTEXT "\ + "[%(request_id)s]: %(message)s", + logging_default_format_string="NOCTXT: %(message)s", + logging_debug_format_suffix="--DBG") + self.log = log.logging.root + self.stream = cStringIO.StringIO() + handler = log.StreamHandler(self.stream) + self.log.addHandler(handler) + self.log.setLevel(log.DEBUG) + + def tearDown(self): + super(NovaFormatterTestCase, self).tearDown() + log.NovaLogger.manager.loggerDict = {} + + def test_uncontextualized_log(self): + self.log.info("foo") + self.assertEqual("NOCTXT: foo\n", self.stream.getvalue()) + + def test_contextualized_log(self): + ctxt = _fake_context() + self.log.info("bar", context=ctxt) + expected = "HAS CONTEXT [%s]: bar\n" % ctxt.request_id + self.assertEqual(expected, self.stream.getvalue()) + + def test_debugging_log(self): + self.log.debug("baz") + self.assertEqual("NOCTXT: baz --DBG\n", self.stream.getvalue()) + +class NovaLoggerTestCase(test.TrialTestCase): + def setUp(self): + super(NovaLoggerTestCase, self).setUp() + self.flags(default_log_levels=["nova-test=AUDIT"], verbose=False) + 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.TrialTestCase): + 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/nova/tests/test_network.py b/nova/tests/test_network.py index 96473ac7..349e20f8 100644 --- a/nova/tests/test_network.py +++ b/nova/tests/test_network.py @@ -20,18 +20,18 @@ Unit Tests for network code """ import IPy import os -import logging from nova import context from nova import db from nova import exception from nova import flags -from nova import service +from nova import log as logging from nova import test from nova import utils from nova.auth import manager FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.network') class NetworkTestCase(test.TestCase): @@ -45,7 +45,6 @@ class NetworkTestCase(test.TestCase): fake_network=True, network_size=16, num_networks=5) - logging.getLogger().setLevel(logging.DEBUG) self.manager = manager.AuthManager() self.user = self.manager.create_user('netuser', 'netuser', 'netuser') self.projects = [] @@ -328,7 +327,7 @@ def lease_ip(private_ip): 'TESTING': '1', 'FLAGFILE': FLAGS.dhcpbridge_flagfile} (out, err) = utils.execute(cmd, addl_env=env) - logging.debug("ISSUE_IP: %s, %s ", out, err) + LOG.debug("ISSUE_IP: %s, %s ", out, err) def release_ip(private_ip): @@ -344,4 +343,4 @@ def release_ip(private_ip): 'TESTING': '1', 'FLAGFILE': FLAGS.dhcpbridge_flagfile} (out, err) = utils.execute(cmd, addl_env=env) - logging.debug("RELEASE_IP: %s, %s ", out, err) + LOG.debug("RELEASE_IP: %s, %s ", out, err) diff --git a/nova/tests/test_rpc.py b/nova/tests/test_rpc.py index 6ea2edca..0e72b3eb 100644 --- a/nova/tests/test_rpc.py +++ b/nova/tests/test_rpc.py @@ -18,15 +18,16 @@ """ Unit Tests for remote procedure calls using queue """ -import logging from nova import context from nova import flags +from nova import logging from nova import rpc from nova import test FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.rpc') class RpcTestCase(test.TestCase): @@ -115,13 +116,13 @@ class TestReceiver(object): @staticmethod def echo(context, value): """Simply returns whatever value is sent in""" - logging.debug("Received %s", value) + LOG.debug(_("Received %s"), value) return value @staticmethod def context(context, value): """Returns dictionary version of context""" - logging.debug("Received %s", context) + LOG.debug(_("Received %s"), context) return context.to_dict() @staticmethod diff --git a/nova/tests/test_volume.py b/nova/tests/test_volume.py index b13455fb..b40ca004 100644 --- a/nova/tests/test_volume.py +++ b/nova/tests/test_volume.py @@ -19,23 +19,23 @@ Tests for Volume Code. """ -import logging from nova import context from nova import exception from nova import db from nova import flags +from nova import log as logging from nova import test from nova import utils FLAGS = flags.FLAGS +LOG = logging.getLogger('nova.tests.volume') class VolumeTestCase(test.TestCase): """Test Case for volumes.""" def setUp(self): - logging.getLogger().setLevel(logging.DEBUG) super(VolumeTestCase, self).setUp() self.compute = utils.import_object(FLAGS.compute_manager) self.flags(connection_type='fake') @@ -159,7 +159,7 @@ class VolumeTestCase(test.TestCase): volume_id) self.assert_(iscsi_target not in targets) targets.append(iscsi_target) - logging.debug("Target %s allocated", iscsi_target) + LOG.debug(_("Target %s allocated"), iscsi_target) total_slots = FLAGS.iscsi_num_targets for _index in xrange(total_slots): volume_id = self._create_volume() diff --git a/nova/twistd.py b/nova/twistd.py index 29be9c4e..55627199 100644 --- a/nova/twistd.py +++ b/nova/twistd.py @@ -22,7 +22,6 @@ manage pid files and support syslogging. """ import gflags -import logging import os import signal import sys @@ -34,6 +33,7 @@ from twisted.python import runtime from twisted.python import usage from nova import flags +from nova import log as logging if runtime.platformType == "win32": @@ -234,22 +234,12 @@ def serve(filename): OptionsClass = WrapTwistedOptions(TwistdServerOptions) options = OptionsClass() argv = options.parseOptions() - logging.getLogger('amqplib').setLevel(logging.WARN) FLAGS.python = filename FLAGS.no_save = True if not FLAGS.pidfile: FLAGS.pidfile = '%s.pid' % name elif FLAGS.pidfile.endswith('twistd.pid'): FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', '%s.pid' % name) - # NOTE(vish): if we're running nodaemon, redirect the log to stdout - if FLAGS.nodaemon and not FLAGS.logfile: - FLAGS.logfile = "-" - if not FLAGS.logfile: - FLAGS.logfile = '%s.log' % name - elif FLAGS.logfile.endswith('twistd.log'): - FLAGS.logfile = FLAGS.logfile.replace('twistd.log', '%s.log' % name) - if FLAGS.logdir: - FLAGS.logfile = os.path.join(FLAGS.logdir, FLAGS.logfile) if not FLAGS.prefix: FLAGS.prefix = name elif FLAGS.prefix.endswith('twisted'): @@ -270,19 +260,10 @@ def serve(filename): print 'usage: %s [options] [start|stop|restart]' % argv[0] sys.exit(1) - formatter = logging.Formatter( - '(%(name)s): %(levelname)s %(message)s') - handler = logging.StreamHandler(log.StdioOnnaStick()) - handler.setFormatter(formatter) - logging.getLogger().addHandler(handler) - - if FLAGS.verbose: - logging.getLogger().setLevel(logging.DEBUG) - else: - logging.getLogger().setLevel(logging.WARNING) - + logging.basicConfig() logging.debug(_("Full set of FLAGS:")) for flag in FLAGS: logging.debug("%s : %s" % (flag, FLAGS.get(flag, None))) + logging.audit(_("Starting %s"), name) twistd.runApp(options) From 80c7e89f3edd984761bc55532c84ca06409648db Mon Sep 17 00:00:00 2001 From: Todd Willey Date: Tue, 4 Jan 2011 00:26:41 -0500 Subject: [PATCH 12/26] Final few log tweaks, i18n, levels, including contexts, etc. --- bin/nova-dhcpbridge | 15 ++++++--------- bin/nova-instancemonitor | 2 +- bin/nova-manage | 2 -- nova/auth/ldapdriver.py | 3 +-- nova/auth/manager.py | 3 +-- nova/rpc.py | 5 +++-- 6 files changed, 12 insertions(+), 18 deletions(-) diff --git a/bin/nova-dhcpbridge b/bin/nova-dhcpbridge index cecc1c80..1a994d95 100755 --- a/bin/nova-dhcpbridge +++ b/bin/nova-dhcpbridge @@ -49,16 +49,13 @@ flags.DECLARE('network_size', 'nova.network.manager') flags.DECLARE('num_networks', 'nova.network.manager') flags.DECLARE('update_dhcp_on_disassociate', 'nova.network.manager') - -LOG = logging.getLogger('nova-dhcpbridge') -if FLAGS.verbose: - LOG.setLevel(logging.DEBUG) +LOG = logging.getLogger('nova.dhcpbridge') def add_lease(mac, ip_address, _hostname, _interface): """Set the IP that was assigned by the DHCP server.""" if FLAGS.fake_rabbit: - LOG.debug("leasing ip") + LOG.debug(_("leasing ip")) network_manager = utils.import_object(FLAGS.network_manager) network_manager.lease_fixed_ip(context.get_admin_context(), mac, @@ -73,14 +70,14 @@ def add_lease(mac, ip_address, _hostname, _interface): def old_lease(mac, ip_address, hostname, interface): """Update just as add lease.""" - LOG.debug("Adopted old lease or got a change of mac/hostname") + LOG.debug(_("Adopted old lease or got a change of mac/hostname")) add_lease(mac, ip_address, hostname, interface) def del_lease(mac, ip_address, _hostname, _interface): """Called when a lease expires.""" if FLAGS.fake_rabbit: - LOG.debug("releasing ip") + LOG.debug(_("releasing ip")) network_manager = utils.import_object(FLAGS.network_manager) network_manager.release_fixed_ip(context.get_admin_context(), mac, @@ -123,8 +120,8 @@ def main(): mac = argv[2] ip = argv[3] hostname = argv[4] - LOG.debug("Called %s for mac %s with ip %s and " - "hostname %s on interface %s", + LOG.debug(_("Called %s for mac %s with ip %s and " + "hostname %s on interface %s"), action, mac, ip, hostname, interface) globals()[action + '_lease'](mac, ip, hostname, interface) else: diff --git a/bin/nova-instancemonitor b/bin/nova-instancemonitor index 17f573b9..7dca0201 100755 --- a/bin/nova-instancemonitor +++ b/bin/nova-instancemonitor @@ -44,7 +44,7 @@ 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') +LOG = logging.getLogger('nova.instancemonitor') if __name__ == '__main__': diff --git a/bin/nova-manage b/bin/nova-manage index 169ab5f6..40f540e5 100755 --- a/bin/nova-manage +++ b/bin/nova-manage @@ -77,7 +77,6 @@ from nova import crypto from nova import db from nova import exception from nova import flags -from nova import log as logging from nova import quota from nova import utils from nova.auth import manager @@ -557,7 +556,6 @@ def main(): utils.default_flagfile() argv = FLAGS(sys.argv) - logging._set_log_levels() script_name = argv.pop(0) if len(argv) < 1: print script_name + " category action []" diff --git a/nova/auth/ldapdriver.py b/nova/auth/ldapdriver.py index 3e0837ba..c8de2002 100644 --- a/nova/auth/ldapdriver.py +++ b/nova/auth/ldapdriver.py @@ -65,7 +65,6 @@ flags.DEFINE_string('ldap_netadmin', flags.DEFINE_string('ldap_developer', 'cn=developers,ou=Groups,dc=example,dc=com', 'cn for Developers') - LOG = logging.getLogger("nova.ldapdriver") @@ -506,7 +505,7 @@ class LdapDriver(object): self.conn.modify_s(group_dn, attr) except self.ldap.OBJECT_CLASS_VIOLATION: LOG.debug(_("Attempted to remove the last member of a group. " - "Deleting the group at %s instead."), group_dn) + "Deleting the group at %s instead."), group_dn) self.__delete_group(group_dn) def __remove_from_all(self, uid): diff --git a/nova/auth/manager.py b/nova/auth/manager.py index bfac7fc2..5685ae5e 100644 --- a/nova/auth/manager.py +++ b/nova/auth/manager.py @@ -70,8 +70,7 @@ flags.DEFINE_string('credential_rc_file', '%src', flags.DEFINE_string('auth_driver', 'nova.auth.dbdriver.DbDriver', 'Driver that auth manager uses') - -LOG = logging.getLogger('nova.authmanager') +LOG = logging.getLogger('nova.auth.manager') class AuthBase(object): diff --git a/nova/rpc.py b/nova/rpc.py index 02052485..bdf2f74b 100644 --- a/nova/rpc.py +++ b/nova/rpc.py @@ -96,8 +96,9 @@ class Consumer(messaging.Consumer): FLAGS.rabbit_retry_interval)) self.failed_connection = True if self.failed_connection: - LOG.exception(_("Unable to connect to AMQP server" - " after %d tries. Shutting down.") % FLAGS.rabbit_max_retries) + LOG.exception(_("Unable to connect to AMQP server " + "after %d tries. Shutting down."), + FLAGS.rabbit_max_retries) sys.exit(1) def fetch(self, no_ack=None, auto_ack=None, enable_callbacks=False): From 4700b1fa8226409ab096fddd6eaa9860b009186a Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Tue, 4 Jan 2011 15:18:28 -0800 Subject: [PATCH 13/26] Merge from trunk again -- get rid of twistd dependencies --- nova/twistd.py | 39 +++++++++++++++++++-------------------- 1 file changed, 19 insertions(+), 20 deletions(-) diff --git a/nova/twistd.py b/nova/twistd.py index 22e2d06d..1dd10dbb 100644 --- a/nova/twistd.py +++ b/nova/twistd.py @@ -237,26 +237,25 @@ def serve(filename): logging.getLogger('amqplib').setLevel(logging.WARN) FLAGS.python = filename FLAGS.no_save = True - if sys.platform != 'win32': - if not FLAGS.pidfile: - FLAGS.pidfile = '%s.pid' % name - elif FLAGS.pidfile.endswith('twistd.pid'): - FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', - '%s.pid' % name) - # NOTE(vish): if we're running nodaemon, redirect the log to stdout - if FLAGS.nodaemon and not FLAGS.logfile: - FLAGS.logfile = "-" - if not FLAGS.logfile: - FLAGS.logfile = '%s.log' % name - elif FLAGS.logfile.endswith('twistd.log'): - FLAGS.logfile = FLAGS.logfile.replace('twistd.log', - '%s.log' % name) - if FLAGS.logdir: - FLAGS.logfile = os.path.join(FLAGS.logdir, FLAGS.logfile) - if not FLAGS.prefix: - FLAGS.prefix = name - elif FLAGS.prefix.endswith('twisted'): - FLAGS.prefix = FLAGS.prefix.replace('twisted', name) + if not FLAGS.pidfile: + FLAGS.pidfile = '%s.pid' % name + elif FLAGS.pidfile.endswith('twistd.pid'): + FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', + '%s.pid' % name) + # NOTE(vish): if we're running nodaemon, redirect the log to stdout + if FLAGS.nodaemon and not FLAGS.logfile: + FLAGS.logfile = "-" + if not FLAGS.logfile: + FLAGS.logfile = '%s.log' % name + elif FLAGS.logfile.endswith('twistd.log'): + FLAGS.logfile = FLAGS.logfile.replace('twistd.log', + '%s.log' % name) + if FLAGS.logdir: + FLAGS.logfile = os.path.join(FLAGS.logdir, FLAGS.logfile) + if not FLAGS.prefix: + FLAGS.prefix = name + elif FLAGS.prefix.endswith('twisted'): + FLAGS.prefix = FLAGS.prefix.replace('twisted', name) action = 'start' if len(argv) > 1: From 791bc2fa113addbabcda8b06a684d74a85a4bf20 Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Tue, 4 Jan 2011 16:06:03 -0800 Subject: [PATCH 14/26] Revert some unneeded formatting since twistd is no longer used --- nova/twistd.py | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/nova/twistd.py b/nova/twistd.py index 1dd10dbb..29be9c4e 100644 --- a/nova/twistd.py +++ b/nova/twistd.py @@ -240,16 +240,14 @@ def serve(filename): if not FLAGS.pidfile: FLAGS.pidfile = '%s.pid' % name elif FLAGS.pidfile.endswith('twistd.pid'): - FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', - '%s.pid' % name) + FLAGS.pidfile = FLAGS.pidfile.replace('twistd.pid', '%s.pid' % name) # NOTE(vish): if we're running nodaemon, redirect the log to stdout if FLAGS.nodaemon and not FLAGS.logfile: FLAGS.logfile = "-" if not FLAGS.logfile: FLAGS.logfile = '%s.log' % name elif FLAGS.logfile.endswith('twistd.log'): - FLAGS.logfile = FLAGS.logfile.replace('twistd.log', - '%s.log' % name) + FLAGS.logfile = FLAGS.logfile.replace('twistd.log', '%s.log' % name) if FLAGS.logdir: FLAGS.logfile = os.path.join(FLAGS.logdir, FLAGS.logfile) if not FLAGS.prefix: From a062c77550897f8912cc2152095a2820c40cc48c Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Tue, 4 Jan 2011 16:20:14 -0800 Subject: [PATCH 15/26] Redis dependency no longer needed --- nova/tests/hyperv_unittest.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/nova/tests/hyperv_unittest.py b/nova/tests/hyperv_unittest.py index 6346ce4c..27a41f19 100644 --- a/nova/tests/hyperv_unittest.py +++ b/nova/tests/hyperv_unittest.py @@ -27,10 +27,6 @@ from nova.virt import hyperv FLAGS = flags.FLAGS FLAGS.connection_type = 'hyperv' -# Redis is probably not running on Hyper-V host. -# Change this to the actual Redis host -FLAGS.redis_host = '127.0.0.1' - class HyperVTestCase(test.TrialTestCase): """Test cases for the Hyper-V driver""" From d113e42699d87391b2a6453d08517256bae6b337 Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Tue, 4 Jan 2011 16:21:27 -0800 Subject: [PATCH 16/26] need one more newline --- nova/tests/hyperv_unittest.py | 1 + 1 file changed, 1 insertion(+) diff --git a/nova/tests/hyperv_unittest.py b/nova/tests/hyperv_unittest.py index 27a41f19..7044db43 100644 --- a/nova/tests/hyperv_unittest.py +++ b/nova/tests/hyperv_unittest.py @@ -28,6 +28,7 @@ from nova.virt import hyperv FLAGS = flags.FLAGS FLAGS.connection_type = 'hyperv' + class HyperVTestCase(test.TrialTestCase): """Test cases for the Hyper-V driver""" def setUp(self): # pylint: disable-msg=C0103 From d12beb3a64e28796b8df9eece76e3e91a8eccb19 Mon Sep 17 00:00:00 2001 From: Todd Willey Date: Wed, 5 Jan 2011 01:54:31 -0500 Subject: [PATCH 17/26] Better method for eventlet.wsgi.server logging. --- nova/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/nova/log.py b/nova/log.py index 88a961e1..97472b20 100644 --- a/nova/log.py +++ b/nova/log.py @@ -67,7 +67,7 @@ flags.DEFINE_string('logging_exception_prefix', flags.DEFINE_list('default_log_levels', ['amqplib=WARN', 'sqlalchemy=WARN', - 'audit=INFO'], + 'eventlet.wsgi.server=WARN'], 'list of logger=LEVEL pairs') flags.DEFINE_bool('use_syslog', False, 'output to syslog') From d08eeac5a95b6b568aecef2a4a8d2b8c06743156 Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Wed, 5 Jan 2011 15:02:09 -0800 Subject: [PATCH 19/26] Make test case work again --- nova/tests/hyperv_unittest.py | 25 ++++++++++++++++--------- 1 file changed, 16 insertions(+), 9 deletions(-) diff --git a/nova/tests/hyperv_unittest.py b/nova/tests/hyperv_unittest.py index 7044db43..3980ae3c 100644 --- a/nova/tests/hyperv_unittest.py +++ b/nova/tests/hyperv_unittest.py @@ -19,31 +19,36 @@ Tests For Hyper-V driver import random +from nova import context from nova import db from nova import flags from nova import test - +from nova.auth import manager from nova.virt import hyperv FLAGS = flags.FLAGS FLAGS.connection_type = 'hyperv' -class HyperVTestCase(test.TrialTestCase): +class HyperVTestCase(test.TestCase): """Test cases for the Hyper-V driver""" - def setUp(self): # pylint: disable-msg=C0103 - pass + def setUp(self): + super(HyperVTestCase, self).setUp() + self.manager = manager.AuthManager() + self.user = self.manager.create_user('fake', 'fake', 'fake', + admin=True) + self.project = self.manager.create_project('fake', 'fake', 'fake') + self.context = context.RequestContext(self.user, self.project) def test_create_destroy(self): """Create a VM and destroy it""" instance = {'internal_id': random.randint(1, 1000000), 'memory_mb': '1024', 'mac_address': '02:12:34:46:56:67', - 'vcpu': 2, + 'vcpus': 2, 'project_id': 'fake', 'instance_type': 'm1.small'} - - instance_ref = db.instance_create(None, instance) + instance_ref = db.instance_create(self.context, instance) conn = hyperv.get_connection(False) conn._create_vm(instance_ref) # pylint: disable-msg=W0212 @@ -60,5 +65,7 @@ class HyperVTestCase(test.TrialTestCase): if n == instance_ref['name']] self.assertTrue(len(found) == 0) - def tearDown(self): # pylint: disable-msg=C0103 - pass + def tearDown(self): + super(HyperVTestCase, self).tearDown() + self.manager.delete_project(self.project) + self.manager.delete_user(self.user) From 796837bf2f3d58a39c080e7475bc5b40a3686605 Mon Sep 17 00:00:00 2001 From: Chiradeep Vittal Date: Wed, 5 Jan 2011 15:04:51 -0800 Subject: [PATCH 20/26] Add to Authors and mailmap --- .mailmap | 1 + Authors | 1 + 2 files changed, 2 insertions(+) diff --git a/.mailmap b/.mailmap index 01067856..2af2d7cd 100644 --- a/.mailmap +++ b/.mailmap @@ -30,3 +30,4 @@ + diff --git a/Authors b/Authors index 639e68a5..8dfaf955 100644 --- a/Authors +++ b/Authors @@ -3,6 +3,7 @@ Anne Gentle Anthony Young Antony Messerli Armando Migliaccio +Chiradeep Vittal Chris Behrens Chmouel Boudjnah Cory Wright From 5c401a339898e1ac8e49a0abb5b89e8c18a94616 Mon Sep 17 00:00:00 2001 From: Vishvananda Ishaya Date: Thu, 6 Jan 2011 18:46:28 +0000 Subject: [PATCH 21/26] fix the broken tests that allowed the breakage in format to happen --- nova/tests/test_cloud.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/nova/tests/test_cloud.py b/nova/tests/test_cloud.py index 42344af1..ba58fab5 100644 --- a/nova/tests/test_cloud.py +++ b/nova/tests/test_cloud.py @@ -140,15 +140,16 @@ class CloudTestCase(test.TestCase): kwargs = {'image_id': image_id, 'instance_type': instance_type, 'max_count': max_count} - rv = yield self.cloud.run_instances(self.context, **kwargs) + rv = self.cloud.run_instances(self.context, **kwargs) + print rv instance_id = rv['instancesSet'][0]['instanceId'] - output = yield self.cloud.get_console_output(context=self.context, + output = self.cloud.get_console_output(context=self.context, instance_id=[instance_id]) self.assertEquals(b64decode(output['output']), 'FAKE CONSOLE OUTPUT') # TODO(soren): We need this until we can stop polling in the rpc code # for unit tests. greenthread.sleep(0.3) - rv = yield self.cloud.terminate_instances(self.context, [instance_id]) + rv = self.cloud.terminate_instances(self.context, [instance_id]) def test_key_generation(self): result = self._create_key('test') @@ -186,7 +187,7 @@ class CloudTestCase(test.TestCase): kwargs = {'image_id': image_id, 'instance_type': instance_type, 'max_count': max_count} - rv = yield self.cloud.run_instances(self.context, **kwargs) + rv = self.cloud.run_instances(self.context, **kwargs) # TODO: check for proper response instance_id = rv['reservationSet'][0].keys()[0] instance = rv['reservationSet'][0][instance_id][0] @@ -209,7 +210,7 @@ class CloudTestCase(test.TestCase): for instance in reservations[reservations.keys()[0]]: instance_id = instance['instance_id'] logging.debug("Terminating instance %s" % instance_id) - rv = yield self.compute.terminate_instance(instance_id) + rv = self.compute.terminate_instance(instance_id) def test_instance_update_state(self): def instance(num): From ecff918d43e7f76ac75c4c111e6a98103a92b3df Mon Sep 17 00:00:00 2001 From: Todd Willey Date: Thu, 6 Jan 2011 15:08:14 -0500 Subject: [PATCH 22/26] pep8 --- nova/log.py | 3 +-- nova/tests/test_log.py | 9 ++++++--- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/nova/log.py b/nova/log.py index 97472b20..6f5377e8 100644 --- a/nova/log.py +++ b/nova/log.py @@ -74,7 +74,6 @@ flags.DEFINE_bool('use_syslog', False, 'output to syslog') flags.DEFINE_string('logfile', None, 'output to named file') - # A list of things we want to replicate from logging. # levels CRITICAL = logging.CRITICAL @@ -112,7 +111,7 @@ def _dictify_context(context): return None if not isinstance(context, dict) \ and getattr(context, 'to_dict', None): - context = context.to_dict() + context = context.to_dict() return context diff --git a/nova/tests/test_log.py b/nova/tests/test_log.py index d8dd3870..beb1d97c 100644 --- a/nova/tests/test_log.py +++ b/nova/tests/test_log.py @@ -35,15 +35,16 @@ class RootLoggerTestCase(test.TrialTestCase): def test_handles_context_kwarg(self): self.log.info("foo", context=_fake_context()) - self.assert_(True) # didn't raise exception + self.assert_(True) # didn't raise exception def test_module_level_methods_handle_context_arg(self): log.info("foo", context=_fake_context()) - self.assert_(True) # didn't raise exception + self.assert_(True) # didn't raise exception def test_module_level_audit_handles_context_arg(self): log.audit("foo", context=_fake_context()) - self.assert_(True) # didn't raise exception + self.assert_(True) # didn't raise exception + class NovaFormatterTestCase(test.TrialTestCase): def setUp(self): @@ -76,6 +77,7 @@ class NovaFormatterTestCase(test.TrialTestCase): self.log.debug("baz") self.assertEqual("NOCTXT: baz --DBG\n", self.stream.getvalue()) + class NovaLoggerTestCase(test.TrialTestCase): def setUp(self): super(NovaLoggerTestCase, self).setUp() @@ -93,6 +95,7 @@ class NovaLoggerTestCase(test.TrialTestCase): l = log.getLogger('nova-test.foo') self.assertEqual(log.AUDIT, l.level) + class VerboseLoggerTestCase(test.TrialTestCase): def setUp(self): super(VerboseLoggerTestCase, self).setUp() From 65128f8df9920ec717529c3334a9f0f3e1af0e15 Mon Sep 17 00:00:00 2001 From: Trey Morris Date: Thu, 6 Jan 2011 16:30:45 -0600 Subject: [PATCH 23/26] pep8 --- nova/tests/test_compute.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/nova/tests/test_compute.py b/nova/tests/test_compute.py index 993c4fd3..062f37f2 100644 --- a/nova/tests/test_compute.py +++ b/nova/tests/test_compute.py @@ -180,12 +180,12 @@ class ComputeTestCase(test.TestCase): # decorator should return False (fail) with locked nonadmin context self.compute.lock_instance(self.context, instance_id) - ret_val = self.compute.reboot_instance(non_admin_context,instance_id) + ret_val = self.compute.reboot_instance(non_admin_context, instance_id) self.assertEqual(ret_val, False) # decorator should return None (success) with unlocked nonadmin context self.compute.unlock_instance(self.context, instance_id) - ret_val = self.compute.reboot_instance(non_admin_context,instance_id) + ret_val = self.compute.reboot_instance(non_admin_context, instance_id) self.assertEqual(ret_val, None) self.compute.terminate_instance(self.context, instance_id) From 8a8e3c46e005c53772f627175f517581a724060d Mon Sep 17 00:00:00 2001 From: Ewan Mellor Date: Fri, 7 Jan 2011 18:15:29 +0000 Subject: [PATCH 24/26] Bug #699910: Nova RPC layer silently swallows exceptions Log exceptions thrown during message handling. --- nova/rpc.py | 1 + 1 file changed, 1 insertion(+) diff --git a/nova/rpc.py b/nova/rpc.py index 84408834..ae5e7792 100644 --- a/nova/rpc.py +++ b/nova/rpc.py @@ -193,6 +193,7 @@ class AdapterConsumer(TopicConsumer): if msg_id: msg_reply(msg_id, rval, None) except Exception as e: + logging.exception("Exception during message handling") if msg_id: msg_reply(msg_id, None, sys.exc_info()) return From 6eab738d8ba002a46c2b64cb0514900e4080d302 Mon Sep 17 00:00:00 2001 From: Todd Willey Date: Fri, 7 Jan 2011 14:09:38 -0500 Subject: [PATCH 26/26] pep8 fixes --- bin/nova-logspool | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/nova-logspool b/bin/nova-logspool index d5aef475..097459b1 100644 --- a/bin/nova-logspool +++ b/bin/nova-logspool @@ -28,7 +28,6 @@ import sys class Request(object): - def __init__(self): self.time = "" self.host = "" @@ -67,6 +66,7 @@ class Request(object): 'host': self.host, 'env': self.env, 'logger': self.logger, 'request_id': self.request_id} + class LogReader(object): def __init__(self, filename): self.filename = filename