yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1101504] Re: Horrible vm create performance problem with latest devstack

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: "Davanum Srinivas \(DIMS\)" <davanum@xxxxxxxxx>
Date: Mon, 18 Mar 2013 12:15:33 -0000
Reply-to: Bug 1101504 <1101504@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
This bug lacks the necessary information to effectively reproduce and
fix it, therefore it has been closed. Feel free to reopen the bug by
providing the requested information and set the bug status back to
''New''.

** Changed in: nova
       Status: Incomplete => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1101504

Title:
  Horrible vm create performance problem with latest devstack

Status in OpenStack Compute (Nova):
  Invalid

Bug description:
  I installed the latest devstack on a clean machine and ran the tempest
  tests. It is taking almost 1.5 minutes to create a vm on a fast
  machine, compared with <10 seconds in a recent jenkins ci run. Booting
  precise (a larger image) in our real folsom cluster with similar
  hardware takes 16 seconds. Comparing the logs, the difference is that
  my log has a call to

   INFO nova.compute.manager [-] Updating host status

  in between "Claim successful" and "Creating image" and the jenkins log
  has no such call. That call is taking well more than a minute. Here is
  the jenkins log snippet followed by my own. I used completely vanilla
  devstack configuration on a precise server (real hardware).

  jenkins:

  2013-01-18 20:22:20.70 AUDIT nova.compute.manager [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Starting instance...
  2013-01-18 20:22:20.163 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Attempting claim: memory 64 MB, disk 0 GB, VCPUs 1
  2013-01-18 20:22:20.165 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Total Memory: 3955 MB, used: 576 MB
  2013-01-18 20:22:20.166 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Memory limit: 5932 MB, free: 5356 MB
  2013-01-18 20:22:20.167 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Total Disk: 100 GB, used: 0 GB
  2013-01-18 20:22:20.167 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Disk limit not specified, defaulting to unlimited
  2013-01-18 20:22:20.168 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Total CPU: 2 VCPUs, used: 1 VCPUs
  2013-01-18 20:22:20.169 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] CPU limit not specified, defaulting to unlimited
  2013-01-18 20:22:20.169 AUDIT nova.compute.claims [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Claim successful
  2013-01-18 20:22:22.639 INFO nova.virt.libvirt.driver [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Creating image
  2013-01-18 20:22:23.154 INFO nova.virt.libvirt.firewall [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Called setup_basic_filtering in nwfilter
  2013-01-18 20:22:23.155 INFO nova.virt.libvirt.firewall [req-a56e0488-0fd3-4920-b928-9552627090c0 FloatingIPsTestXML751830-user FloatingIPsTestXML751830-tenant] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Ensuring static filters
  2013-01-18 20:22:23.585 16733 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
  2013-01-18 20:22:23.805 16733 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 3315
  2013-01-18 20:22:23.805 16733 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 100
  2013-01-18 20:22:23.806 16733 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 0
  2013-01-18 20:22:23.866 16733 INFO nova.compute.resource_tracker [-] Compute_service record updated for devstack-1358532083 
  2013-01-18 20:22:23.866 16733 INFO nova.compute.manager [-] Updating host status
  2013-01-18 20:22:25.334 16733 INFO nova.virt.libvirt.driver [-] [instance: f2d5a62e-4e0a-4753-bef7-8e21f0f48855] Instance spawned successfully.
  201

  
  My devstack:
  2013-01-18 16:33:22.870 AUDIT nova.compute.manager [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Starting instance...
  2013-01-18 16:33:22.871 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:22.871 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 5f711d75d56b43ab8da68ed543665d21 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:23.1 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:23.2 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 01818c31e79b4cf5a70176f11711eb5b multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:24.346 23899 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/instance-00000043/disk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:33:24.362 23899 DEBUG nova.utils [-] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:33:24.363 23899 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/instance-00000043/disk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:33:24.378 23899 DEBUG nova.utils [-] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:33:25.242 23899 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/instance-00000040/disk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:33:25.257 23899 DEBUG nova.utils [-] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:33:25.258 23899 DEBUG nova.utils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/instance-00000040/disk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:33:25.274 23899 DEBUG nova.utils [-] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:33:25.275 23899 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 46007 _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:325
  2013-01-18 16:33:25.275 23899 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 85 _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:326
  2013-01-18 16:33:25.275 23899 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 14 _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:331
  2013-01-18 16:33:25.276 23899 DEBUG nova.openstack.common.rpc.amqp [-] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:25.276 23899 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is b2cea018db4c402ab4feecf4f80503b2 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:25.327 23899 DEBUG nova.openstack.common.rpc.amqp [-] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:25.328 23899 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is dd9c22fcef7145448d21d7919217b832 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:25.357 23899 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 47015
  2013-01-18 16:33:25.357 23899 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 91
  2013-01-18 16:33:25.357 23899 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 13
  2013-01-18 16:33:25.426 23899 INFO nova.compute.resource_tracker [-] Compute_service record updated for xg08eth0.qrclab.com
  2013-01-18 16:33:25.426 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "compute_resources" for method "instance_claim"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:33:25.430 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Attempting claim: memory 512 MB, disk 0 GB, VCPUs 1
  2013-01-18 16:33:25.430 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Total Memory: 48167 MB, used: 1152 MB
  2013-01-18 16:33:25.431 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Memory limit: 72250 MB, free: 71098 MB
  2013-01-18 16:33:25.432 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Total Disk: 91 GB, used: 0 GB
  2013-01-18 16:33:25.432 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Disk limit not specified, defaulting to unlimited
  2013-01-18 16:33:25.433 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Total CPU: 16 VCPUs, used: 3 VCPUs
  2013-01-18 16:33:25.434 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] CPU limit not specified, defaulting to unlimited
  2013-01-18 16:33:25.434 AUDIT nova.compute.claims [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Claim successful
  2013-01-18 16:33:25.435 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:25.436 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is b57e7688f7494667bf5d2b0586d093ef multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:25.437 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:25.437 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._reclaim_queued_deletes periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:25.438 23899 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /opt/stack/nova/nova/compute/manager.py:3416
  2013-01-18 16:33:25.438 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._report_driver_status periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:25.438 23899 INFO nova.compute.manager [-] Updating host status
  2013-01-18 16:33:25.438 23899 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /opt/stack/nova/nova/virt/libvirt/driver.py:3170
  2013-01-18 16:33:25.577 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:25.577 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is a970f0a3cb5946f2acebe409d9f8deee multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:25.679 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Updating host stats update_status /opt/stack/nova/nova/virt/libvirt/driver.py:3170
  2013-01-18 16:33:46.387 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:46.387 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rescued_instances periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:46.387 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_bandwidth_usage periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:46.388 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:46.388 23899 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache periodic_tasks /opt/stack/nova/nova/manager.py:226
  2013-01-18 16:33:46.388 23899 DEBUG nova.openstack.common.rpc.amqp [-] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:46.389 23899 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is 41d321376eea44dfa08e8bedc6780f34 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:46.458 23899 DEBUG nova.openstack.common.rpc.amqp [-] Making synchronous call on network ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:46.458 23899 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is dc568da9efad4c6b8588088c592f25f4 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:46.547 23899 DEBUG nova.openstack.common.rpc.amqp [-] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:46.547 23899 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is 0737bf3b25a94ff399d8cd0d064be722 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:46.567 23899 DEBUG nova.compute.manager [-] [instance: 3b7dbcd2-38cf-4ba2-b4aa-188a0e8bd315] Updated the info_cache for instance _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:2989
  2013-01-18 16:33:46.568 23899 DEBUG nova.utils [-] Periodic task processor sleeping for 60.00 seconds _inner /opt/stack/nova/nova/utils.py:627
  2013-01-18 16:33:48.972 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "compute_resources" for method "update_usage"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:33:49.34 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on network ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:49.35 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 8b3c0e4073754ed0a8ef313f814c2f3b multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:51.560 DEBUG nova.compute.manager [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Instance network_info: |[VIF({'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.0.0.5'})], 'version': 4, 'meta': {u'dhcp_server': u'10.0.0.1\
  '}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.0.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.0.0.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})}\
  )], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'b82bd537-b79d-4467-a9eb-fbfec0cfa241', 'label': u'private'}), 'devname': None, 'meta': {}, 'address': u'fa:16:3e:82:11:ee', 'type': u'bridge', 'id': u'dfd76a18-0eb0-44b3-a6b1-c775609436d1'})]| _allocate_network /opt/stack/nova/nova/compute/manager.py:933
  2013-01-18 16:33:51.561 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:33:51.562 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 879ba27a0e6d4c48bb7d9b5122f5a0e2 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:33:51.663 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Updating host stats update_status /opt/stack/nova/nova/virt/libvirt/driver.py:3170
  2013-01-18 16:34:03.580 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "compute_resources" for method "update_usage"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:03.663 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:34:03.664 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 01b2cfafe5e64f32a466d666e9c52e65 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:34:03.783 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Updating host stats update_status /opt/stack/nova/nova/virt/libvirt/driver.py:3170
  2013-01-18 16:34:15.684 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "compute_resources" for method "update_usage"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:15.743 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Starting toXML method to_xml /opt/stack/nova/nova/virt/libvirt/driver.py:1858
  2013-01-18 16:34:15.744 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:34:15.744 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 6ef6346f1c504942879a08a4e89560bb multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:34:15.845 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Updating host stats update_status /opt/stack/nova/nova/virt/libvirt/driver.py:3170
  2013-01-18 16:34:27.395 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "compute_resources" for method "update_usage"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:30.782 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] block_device_list [] _volume_in_mapping /opt/stack/nova/nova/virt/libvirt/driver.py:1440
  2013-01-18 16:34:30.783 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] block_device_list [] _volume_in_mapping /opt/stack/nova/nova/virt/libvirt/driver.py:1440
  2013-01-18 16:34:30.784 DEBUG nova.virt.libvirt.vif [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Ensuring bridge br100 plug /opt/stack/nova/nova/virt/libvirt/vif.py:133
  2013-01-18 16:34:30.784 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "lock_bridge" for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:30.785 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "lock_bridge" for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:30.786 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "lock_bridge" at /opt/stack/data/nova/nova-lock_bridge for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:30.787 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link show dev br100 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:30.899 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:30.900 DEBUG nova.network.linux_net [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Adding interface eth0 to bridge br100 ensure_bridge /opt/stack/nova/nova/network/linux_net.py:1298
  2013-01-18 16:34:30.901 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif br100 eth0 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.13 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 1 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.14 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): ip route show dev eth0 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.23 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.24 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip addr show dev eth0 scope global execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.137 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.139 DEBUG nova.virt.libvirt.config [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Generated XML <domain type="kvm">
    <uuid>d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6</uuid>
    <name>instance-00000044</name>
    <memory>524288</memory>
    <vcpu>1</vcpu>
    <sysinfo type="smbios">
      <system>
        <entry name="manufacturer">OpenStack Foundation</entry>
        <entry name="product">OpenStack Nova</entry>
        <entry name="version">2013.1</entry>
        <entry name="serial">2b4223b1-e47a-0010-b5d3-60eb69dc012e</entry>
        <entry name="uuid">d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6</entry>
      </system>
    </sysinfo>
    <os>
      <type>hvm</type>
      <kernel>/opt/stack/data/nova/instances/instance-00000044/kernel</kernel>
      <initrd>/opt/stack/data/nova/instances/instance-00000044/ramdisk</initrd>
      <cmdline>root=/dev/vda console=ttyS0</cmdline>
      <smbios mode="sysinfo"/>
    </os>
    <features>
      <acpi/>
      <apic/>
    </features>
    <clock offset="utc">
      <timer name="pit" tickpolicy="delay"/>
      <timer name="rtc" tickpolicy="catchup"/>
    </clock>
    <devices>
      <disk type="file" device="disk">
        <driver name="qemu" type="qcow2" cache="none"/>
        <source file="/opt/stack/data/nova/instances/instance-00000044/disk"/>
        <target bus="virtio" dev="vda"/>
      </disk>
      <interface type="bridge">
        <mac address="fa:16:3e:82:11:ee"/>
        <model type="virtio"/>
        <source bridge="br100"/>
        <filterref filter="nova-instance-instance-00000044-fa163e8211ee">
          <parameter name="IP" value="10.0.0.5"/>
          <parameter name="DHCPSERVER" value="10.0.0.1"/>
        </filterref>
      </interface>
      <serial type="file">
        <source path="/opt/stack/data/nova/instances/instance-00000044/console.log"/>
      </serial>
      <serial type="pty"/>
      <input type="tablet" bus="usb"/>
      <graphics type="vnc" autoport="yes" keymap="en-us" listen="127.0.0.1"/>
    </devices>
  </domain>
    to_xml /opt/stack/nova/nova/virt/libvirt/config.py:70
  2013-01-18 16:34:31.141 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Finished toXML method to_xml /opt/stack/nova/nova/virt/libvirt/driver.py:1862
  2013-01-18 16:34:31.142 INFO nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Creating image
  2013-01-18 16:34:31.143 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "d1a3cbdb-2fcd-4ddf-a217-524955cc8372" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.144 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "d1a3cbdb-2fcd-4ddf-a217-524955cc8372" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.144 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "d1a3cbdb-2fcd-4ddf-a217-524955cc8372" at /opt/stack/data/nova/instances/locks/nova-d1a3cbdb-2fcd-4ddf-a217-524955cc8372 for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:31.145 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "/opt/stack/data/nova/instances/_base/d1a3cbdb-2fcd-4ddf-a217-524955cc8372" for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.146 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "/opt/stack/data/nova/instances/_base/d1a3cbdb-2fcd-4ddf-a217-524955cc8372" for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.146 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "/opt/stack/data/nova/instances/_base/d1a3cbdb-2fcd-4ddf-a217-524955cc8372" at /opt/stack/data/nova/instances/locks/nova-_opt_stack_data_nova_instances__base_d1a3cbdb-2fcd-4ddf-a217-524955cc8372 for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/l\
  ockutils.py:219
  2013-01-18 16:34:31.147 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): cp /opt/stack/data/nova/instances/_base/d1a3cbdb-2fcd-4ddf-a217-524955cc8372 /opt/stack/data/nova/instances/instance-00000044/kernel execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.160 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.162 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.162 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.163 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" at /opt/stack/data/nova/instances/locks/nova-1e7d6d45-e179-41ce-9f0c-a2ce681ecd63 for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:31.164 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "/opt/stack/data/nova/instances/_base/1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.165 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "/opt/stack/data/nova/instances/_base/1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.166 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "/opt/stack/data/nova/instances/_base/1e7d6d45-e179-41ce-9f0c-a2ce681ecd63" at /opt/stack/data/nova/instances/locks/nova-_opt_stack_data_nova_instances__base_1e7d6d45-e179-41ce-9f0c-a2ce681ecd63 for method "copy_raw_image"... inner /opt/stack/nova/nova/openstack/common/l\
  ockutils.py:219
  2013-01-18 16:34:31.166 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): cp /opt/stack/data/nova/instances/_base/1e7d6d45-e179-41ce-9f0c-a2ce681ecd63 /opt/stack/data/nova/instances/instance-00000044/ramdisk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.177 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.179 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] block_device_list [] _volume_in_mapping /opt/stack/nova/nova/virt/libvirt/driver.py:1440
  2013-01-18 16:34:31.180 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "95260ed2eaa1c4a84da6ac2a13717ac919f2447b" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.180 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "95260ed2eaa1c4a84da6ac2a13717ac919f2447b" for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.181 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "95260ed2eaa1c4a84da6ac2a13717ac919f2447b" at /opt/stack/data/nova/instances/locks/nova-95260ed2eaa1c4a84da6ac2a13717ac919f2447b for method "call_if_not_exists"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:31.182 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "/opt/stack/data/nova/instances/_base/95260ed2eaa1c4a84da6ac2a13717ac919f2447b" for method "copy_qcow2_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.183 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "/opt/stack/data/nova/instances/_base/95260ed2eaa1c4a84da6ac2a13717ac919f2447b" for method "copy_qcow2_image"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.184 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "/opt/stack/data/nova/instances/_base/95260ed2eaa1c4a84da6ac2a13717ac919f2447b" at /opt/stack/data/nova/instances/locks/nova-_opt_stack_data_nova_instances__base_95260ed2eaa1c4a84da6ac2a13717ac919f2447b for method "copy_qcow2_image"... inner /opt/stack/nova/nova/openstac\
  k/common/lockutils.py:219
  2013-01-18 16:34:31.185 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/_base/95260ed2eaa1c4a84da6ac2a13717ac919f2447b execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.200 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.201 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/95260ed2eaa1c4a84da6ac2a13717ac919f2447b /opt/stack/data/nova/instances/instance-00000044/disk execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.308 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.310 DEBUG nova.virt.libvirt.vif [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Ensuring bridge br100 plug /opt/stack/nova/nova/virt/libvirt/vif.py:133
  2013-01-18 16:34:31.311 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "lock_bridge" for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:31.311 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "lock_bridge" for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:31.312 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "lock_bridge" at /opt/stack/data/nova/nova-lock_bridge for method "ensure_bridge"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:31.313 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link show dev br100 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.426 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.427 DEBUG nova.network.linux_net [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Adding interface eth0 to bridge br100 ensure_bridge /opt/stack/nova/nova/network/linux_net.py:1298
  2013-01-18 16:34:31.428 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif br100 eth0 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.542 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 1 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.543 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): ip route show dev eth0 execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.550 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.551 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip addr show dev eth0 scope global execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:31.659 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:31.661 INFO nova.virt.libvirt.firewall [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Called setup_basic_filtering in nwfilter
  2013-01-18 16:34:31.662 INFO nova.virt.libvirt.firewall [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Ensuring static filters
  2013-01-18 16:34:32.576 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:34:32.577 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 9f0d2f96ff2848e1b2a2f8f51dcf05c2 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:34:32.609 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:34:32.610 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is 054a47237ca141488e02a4df3d3ffb02 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:34:32.650 DEBUG nova.virt.firewall [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Filters added to instance prepare_instance_filter /opt/stack/nova/nova/virt/firewall.py:190
  2013-01-18 16:34:32.650 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "iptables" for method "_do_refresh_provider_fw_rules"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:32.651 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "iptables" for method "_do_refresh_provider_fw_rules"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:32.652 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "iptables" at /opt/stack/data/nova/nova-iptables for method "_do_refresh_provider_fw_rules"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:32.653 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Making synchronous call on conductor ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
  2013-01-18 16:34:32.654 DEBUG nova.openstack.common.rpc.amqp [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] MSG_ID is f0a1facd9070404da7a9c15026bc7f60 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:365
  2013-01-18 16:34:32.672 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "iptables" for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:32.673 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "iptables" for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:32.673 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "iptables" at /opt/stack/data/nova/nova-iptables for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:32.674 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t filter execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:32.785 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:32.789 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:32.900 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:32.901 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t mangle execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.13 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.14 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.128 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.129 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t nat execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.248 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.249 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.365 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.366 DEBUG nova.network.linux_net [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] IPTablesManager.apply completed with success _apply /opt/stack/nova/nova/network/linux_net.py:385
  2013-01-18 16:34:33.367 DEBUG nova.virt.firewall [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Provider Firewall Rules refreshed prepare_instance_filter /opt/stack/nova/nova/virt/firewall.py:192
  2013-01-18 16:34:33.368 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got semaphore "iptables" for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
  2013-01-18 16:34:33.369 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Attempting to grab file lock "iptables" for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:189
  2013-01-18 16:34:33.369 DEBUG nova.openstack.common.lockutils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Got file lock "iptables" at /opt/stack/data/nova/nova-iptables for method "_apply"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:219
  2013-01-18 16:34:33.370 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t filter execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.483 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.487 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.601 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.602 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t mangle execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.715 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.716 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.838 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.839 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c -t nat execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:33.952 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:33.954 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:34.75 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:34.76 DEBUG nova.network.linux_net [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] IPTablesManager.apply completed with success _apply /opt/stack/nova/nova/network/linux_net.py:385
  2013-01-18 16:34:37.326 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/vnet2/brport/hairpin_mode execute /opt/stack/nova/nova/utils.py:201
  2013-01-18 16:34:37.444 DEBUG nova.utils [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:225
  2013-01-18 16:34:37.445 DEBUG nova.virt.libvirt.driver [req-bbf66f57-6744-4f80-bc47-e2840abb5f98 demo demo] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Instance is running spawn /opt/stack/nova/nova/virt/libvirt/driver.py:1039
  2013-01-18 16:34:38.284 23899 INFO nova.virt.libvirt.driver [-] [instance: d3f7e4cb-34f0-4a5a-abfa-30f4e018dbc6] Instance spawned successfully.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1101504/+subscriptions