Attachment 928858 Details for Bug 1132053 – sequence of atach detach delete detach

sequence of atach detach delete detach

file_1132053.txt (text/plain), 66.19 KB, created by Jaroslav Henner on 2014-08-20 14:50:48 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jaroslav Henner

Created: 2014-08-20 14:50:48 UTC

Size: 66.19 KB

patch

obsolete

>
>2014-08-20 10:46:45.314 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Got semaphore "542dbe02-fc5c-46b0-a620-f6b59f25e66f" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:46:45.316 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Got semaphore / lock "do_reserve" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:46:45.331 16556 DEBUG nova.compute.utils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Using /dev/vd instead of None get_next_device_name /usr/lib/python2.6/site-packages/nova/compute/utils.py:209
>2014-08-20 10:46:45.373 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Semaphore / lock released "do_reserve" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:46:45.642 16556 AUDIT nova.compute.manager [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Attaching volume 14bab350-200e-471d-be99-38d39d24b2fc to /dev/vdb
>2014-08-20 10:46:45.643 16556 DEBUG nova.volume.cinder [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:45.645 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:45.762 16556 DEBUG urllib3.connectionpool [-] "GET /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc HTTP/1.1" 200 567 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:45.763 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:45.818 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 1 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:45.819 16556 DEBUG nova.virt.libvirt.driver [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Could not determine fibre channel world wide node names get_volume_connector /usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py:1153
>2014-08-20 10:46:45.819 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:45.871 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 1 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:45.872 16556 DEBUG nova.virt.libvirt.driver [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Could not determine fibre channel world wide port names get_volume_connector /usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py:1160
>2014-08-20 10:46:45.872 16556 DEBUG nova.volume.cinder [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:45.874 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:46.846 16556 DEBUG urllib3.connectionpool [-] "POST /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/action HTTP/1.1" 200 449 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:46.847 16556 DEBUG nova.volume.cinder [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:46.848 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:46.914 16556 DEBUG urllib3.connectionpool [-] "GET /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/encryption HTTP/1.1" 200 209 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:46.924 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Got semaphore "connect_volume" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:46:46.925 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Got semaphore / lock "connect_volume" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:46:46.927 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:46.998 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 21 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:46.999 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --op new execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.058 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.058 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--op', 'new'): stdout=New iSCSI node [tcp:[hw=,ip=,net_if=,iscsi_if=default] 172.16.40.15,3260,-1 iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc] added
> stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:47.059 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --op update -n node.session.auth.authmethod -v CHAP execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.114 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.114 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.authmethod', '-v', u'CHAP'): stdout= stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:47.115 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --op update -n node.session.auth.username -v dSMxnwgyfAAqc3TXKnpZ execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.169 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.170 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.username', '-v', u'dSMxnwgyfAAqc3TXKnpZ'): stdout= stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:47.170 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --op update -n node.session.auth.password -v D3TCzxewMuQ8wjFx5WMu execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.225 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.226 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.password', '-v', u'D3TCzxewMuQ8wjFx5WMu'): stdout= stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:47.226 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m session execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.281 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.282 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ['-m', 'session']: stdout=tcp: [1] 172.16.40.15:3260,1 iqn.2010-10.org.openstack:volume-6a83279e-a0d6-41cd-ba00-cedaa99734c4
>tcp: [12] 172.16.40.15:3260,1 iqn.2010-10.org.openstack:volume-bcd92e1f-b503-4bfb-b611-ced9f31a030b
>tcp: [18] 172.16.40.15:3260,1 iqn.2010-10.org.openstack:volume-f95a2ddf-86f2-4908-b5ab-dc97dff5b557
> stderr= _run_iscsiadm_bare /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:581
>2014-08-20 10:46:47.282 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --login execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.393 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.394 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.394 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.395 16556 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:46:47.395 16556 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:46:47.395 16556 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-08-20 10:46:47.395 16556 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py:5320
>2014-08-20 10:46:47.467 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/aa285a66-f2d1-481e-8b5c-ad907d5e70ac/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.479 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.480 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/aa285a66-f2d1-481e-8b5c-ad907d5e70ac/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.490 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.496 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/83894851-f636-4810-9d1b-d3b9adf0863d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.506 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.507 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/83894851-f636-4810-9d1b-d3b9adf0863d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.517 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.522 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/46b4d6f2-3ed5-4d4e-b9af-e41a226b522d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.533 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.534 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/46b4d6f2-3ed5-4d4e-b9af-e41a226b522d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.544 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.549 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/542dbe02-fc5c-46b0-a620-f6b59f25e66f/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.559 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.560 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/542dbe02-fc5c-46b0-a620-f6b59f25e66f/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:47.571 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:47.596 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 3162 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:409
>2014-08-20 10:46:47.597 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 74 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:410
>2014-08-20 10:46:47.597 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 0 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:415
>2014-08-20 10:46:47.597 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:422
>2014-08-20 10:46:47.702 16556 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 5758
>2014-08-20 10:46:47.703 16556 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 75
>2014-08-20 10:46:47.703 16556 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 0
>2014-08-20 10:46:47.729 16556 INFO nova.compute.resource_tracker [-] Compute_service record updated for is-busy.novalocal:is-busy.novalocal
>2014-08-20 10:46:47.730 16556 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:46:47.751 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.752 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.752 16556 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.6/site-packages/nova/compute/manager.py:5430
>2014-08-20 10:46:47.752 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.752 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.752 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._run_pending_deletes run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.753 16556 DEBUG nova.compute.manager [-] Cleaning up deleted instances _run_pending_deletes /usr/lib/python2.6/site-packages/nova/compute/manager.py:5715
>2014-08-20 10:46:47.774 16556 DEBUG nova.compute.manager [-] There are 0 instances to clean _run_pending_deletes /usr/lib/python2.6/site-packages/nova/compute/manager.py:5724
>2014-08-20 10:46:47.775 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:47.775 16556 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 11.34 seconds _inner /usr/lib/python2.6/site-packages/nova/openstack/common/loopingcall.py:132
>2014-08-20 10:46:48.284 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:48.285 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--login',): stdout=Logging in to [iface: default, target: iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc, portal: 172.16.40.15,3260] (multiple)
>Login to [iface: default, target: iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc, portal: 172.16.40.15,3260] successful.
> stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:48.285 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --op update -n node.startup -v automatic execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:48.352 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:48.354 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--op', 'update', '-n', 'node.startup', '-v', 'automatic'): stdout= stderr= _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:48.354 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --rescan execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:48.412 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:48.413 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--rescan',): stdout=Rescanning session [sid: 19, target: iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc, portal: 172.16.40.15,3260]
> stderr=iscsiadm: invalid error code 65280
>iscsiadm: Could not execute operation on all sessions: (null)
> _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:48.413 16556 WARNING nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] ISCSI volume not yet found at: vdb. Will rescan & retry.  Try number: 0
>2014-08-20 10:46:48.413 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc -p 172.16.40.15:3260 --rescan execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:48.469 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:48.470 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] iscsiadm ('--rescan',): stdout=Rescanning session [sid: 19, target: iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc, portal: 172.16.40.15,3260]
> stderr=iscsiadm: invalid error code 65280
>iscsiadm: Could not execute operation on all sessions: (null)
> _run_iscsiadm /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:248
>2014-08-20 10:46:49.471 16556 DEBUG nova.virt.libvirt.volume [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Found iSCSI node vdb (after 1 rescans) connect_volume /usr/lib/python2.6/site-packages/nova/virt/libvirt/volume.py:323
>2014-08-20 10:46:49.471 16556 DEBUG nova.openstack.common.lockutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Semaphore / lock released "connect_volume" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:46:49.482 16556 WARNING nova.keymgr.single_key_mgr [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] This key manager is insecure and is not recommended for production deployments
>2014-08-20 10:46:49.482 16556 WARNING nova.keymgr.mock_key_mgr [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] This key manager is not suitable for use in production deployments
>2014-08-20 10:46:49.483 16556 WARNING nova.keymgr.single_key_mgr [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] This key manager is insecure and is not recommended for production deployments
>2014-08-20 10:46:49.483 16556 WARNING nova.keymgr.mock_key_mgr [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] This key manager is not suitable for use in production deployments
>2014-08-20 10:46:49.483 16556 DEBUG nova.volume.encryptors.cryptsetup [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] opening encrypted volume /dev/sdd _open_volume /usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py:54
>2014-08-20 10:46:49.484 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup create --key-file=- --cipher aes-xts-plain64 --key-size 512 ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 /dev/sdd execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:49.844 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:49.845 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ln --symbolic --force /dev/mapper/ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 /dev/disk/by-path/ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:49.897 16556 DEBUG nova.openstack.common.processutils [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:49.898 16556 DEBUG nova.virt.libvirt.config [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Generated XML ('<disk type="block" device="disk">\n  <driver name="qemu" type="raw" cache="none"/>\n  <source dev="/dev/disk/by-path/ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1"/>\n  <target bus="virtio" dev="vdb"/>\n  <serial>14bab350-200e-471d-be99-38d39d24b2fc</serial>\n</disk>\n',)  to_xml /usr/lib/python2.6/site-packages/nova/virt/libvirt/config.py:71
>2014-08-20 10:46:50.049 16556 DEBUG nova.volume.cinder [req-80d2ca3b-a136-44d6-894b-747b957d1761 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:50.051 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:50.553 16556 DEBUG urllib3.connectionpool [-] "POST /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:51.711 16556 AUDIT nova.compute.manager [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Detach volume 14bab350-200e-471d-be99-38d39d24b2fc from mountpoint /dev/vdb
>2014-08-20 10:46:51.720 16556 DEBUG nova.volume.cinder [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:51.721 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:51.791 16556 DEBUG urllib3.connectionpool [-] "GET /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/encryption HTTP/1.1" 200 209 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:51.967 16556 WARNING nova.keymgr.single_key_mgr [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] This key manager is insecure and is not recommended for production deployments
>2014-08-20 10:46:51.967 16556 WARNING nova.keymgr.mock_key_mgr [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] This key manager is not suitable for use in production deployments
>2014-08-20 10:46:51.967 16556 WARNING nova.keymgr.single_key_mgr [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] This key manager is insecure and is not recommended for production deployments
>2014-08-20 10:46:51.968 16556 WARNING nova.keymgr.mock_key_mgr [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] This key manager is not suitable for use in production deployments
>2014-08-20 10:46:51.968 16556 DEBUG nova.volume.encryptors.cryptsetup [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] closing encrypted volume /dev/dm-9 _close_volume /usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py:95
>2014-08-20 10:46:51.968 16556 DEBUG nova.openstack.common.processutils [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:52.161 16556 DEBUG nova.openstack.common.processutils [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Result was 5 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:52.162 16556 ERROR nova.compute.manager [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Failed to detach volume 14bab350-200e-471d-be99-38d39d24b2fc from /dev/vdb
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Traceback (most recent call last):
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     encryption=encryption)
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1387, in detach_volume
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     encryptor.detach_volume(**encryption)
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 101, in detach_volume
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     self._close_volume(**kwargs)
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 97, in _close_volume
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     run_as_root=True, check_exit_code=True)
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/utils.py", line 165, in execute
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     return processutils.execute(*cmd, **kwargs)
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py", line 193, in execute
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     cmd=' '.join(cmd))
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] ProcessExecutionError: Unexpected error while running command.
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Exit code: 5
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Stdout: ''
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Stderr: 'Device ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 is busy.\n'
>2014-08-20 10:46:52.162 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] 
>2014-08-20 10:46:52.163 16556 DEBUG nova.volume.cinder [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:46:52.165 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:46:52.218 16556 DEBUG urllib3.connectionpool [-] "POST /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:46:52.292 16556 DEBUG nova.openstack.common.lockutils [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Got semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:46:52.293 16556 DEBUG nova.openstack.common.lockutils [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Got semaphore / lock "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:46:52.312 16556 DEBUG nova.openstack.common.lockutils [req-e5102e76-1c2a-4820-842e-6108a4d903d5 admin admin] Semaphore / lock released "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:46:52.320 16556 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: Unexpected error while running command.
>Command: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1
>Exit code: 5
>Stdout: ''
>Stderr: 'Device ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 is busy.\n'
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     payload)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     pass
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1387, in detach_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     encryptor.detach_volume(**encryption)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 101, in detach_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     self._close_volume(**kwargs)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 97, in _close_volume
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     run_as_root=True, check_exit_code=True)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/utils.py", line 165, in execute
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     return processutils.execute(*cmd, **kwargs)
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py", line 193, in execute
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher     cmd=' '.join(cmd))
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher ProcessExecutionError: Unexpected error while running command.
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher Command: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher Exit code: 5
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher Stdout: ''
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher Stderr: 'Device ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 is busy.\n'
>2014-08-20 10:46:52.320 16556 TRACE oslo.messaging.rpc.dispatcher 
>2014-08-20 10:46:52.321 16556 ERROR oslo.messaging._drivers.common [-] Returning exception Unexpected error while running command.
>Command: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1
>Exit code: 5
>Stdout: ''
>Stderr: 'Device ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 is busy.\n' to caller
>2014-08-20 10:46:52.321 16556 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1387, in detach_volume\n    encryptor.detach_volume(**encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 101, in detach_volume\n    self._close_volume(**kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/volume/encryptors/cryptsetup.py", line 97, in _close_volume\n    run_as_root=True, check_exit_code=True)\n', '  File "/usr/lib/python2.6/site-packages/nova/utils.py", line 165, in execute\n    return processutils.execute(*cmd, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py", line 193, in execute\n    cmd=\' \'.join(cmd))\n', "ProcessExecutionError: Unexpected error while running command.\nCommand: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup remove ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1\nExit code: 5\nStdout: ''\nStderr: 'Device ip-172.16.40.15:3260-iscsi-iqn.2010-10.org.openstack:volume-14bab350-200e-471d-be99-38d39d24b2fc-lun-1 is busy.\\n'\n"]
>2014-08-20 10:46:59.112 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.113 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.113 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.113 16556 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:46:59.113 16556 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:46:59.114 16556 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-08-20 10:46:59.114 16556 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py:5320
>2014-08-20 10:46:59.176 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/aa285a66-f2d1-481e-8b5c-ad907d5e70ac/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.187 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.188 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/aa285a66-f2d1-481e-8b5c-ad907d5e70ac/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.197 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.203 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/83894851-f636-4810-9d1b-d3b9adf0863d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.213 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.213 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/83894851-f636-4810-9d1b-d3b9adf0863d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.223 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.228 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/46b4d6f2-3ed5-4d4e-b9af-e41a226b522d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.238 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.238 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/46b4d6f2-3ed5-4d4e-b9af-e41a226b522d/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.248 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.254 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/542dbe02-fc5c-46b0-a620-f6b59f25e66f/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.265 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.266 16556 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/542dbe02-fc5c-46b0-a620-f6b59f25e66f/disk execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:154
>2014-08-20 10:46:59.275 16556 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.6/site-packages/nova/openstack/common/processutils.py:187
>2014-08-20 10:46:59.304 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 3080 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:409
>2014-08-20 10:46:59.304 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 74 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:410
>2014-08-20 10:46:59.304 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 0 _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:415
>2014-08-20 10:46:59.305 16556 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.6/site-packages/nova/compute/resource_tracker.py:422
>2014-08-20 10:46:59.402 16556 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 5758
>2014-08-20 10:46:59.403 16556 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 75
>2014-08-20 10:46:59.403 16556 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 0
>2014-08-20 10:46:59.446 16556 INFO nova.compute.resource_tracker [-] Compute_service record updated for is-busy.novalocal:is-busy.novalocal
>2014-08-20 10:46:59.447 16556 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:46:59.500 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.501 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.502 16556 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.6/site-packages/nova/compute/manager.py:5430
>2014-08-20 10:46:59.502 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.503 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.504 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.504 16556 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:178
>2014-08-20 10:46:59.505 16556 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.6/site-packages/nova/compute/manager.py:4851
>2014-08-20 10:47:00.001 16556 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.3'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.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'lo'}, 'id': u'94db1988-71f8-4e26-b3ad-64bd824f9fc3', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:fe:45:40', 'active': False, 'type': u'bridge', 'id': u'bfa1528c-739a-414c-8a6f-02fc0f3dc654', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.6/site-packages/nova/network/api.py:75
>2014-08-20 10:47:00.053 16556 DEBUG nova.compute.manager [-] [instance: aa285a66-f2d1-481e-8b5c-ad907d5e70ac] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.6/site-packages/nova/compute/manager.py:4912
>2014-08-20 10:47:00.054 16556 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.6/site-packages/nova/openstack/common/loopingcall.py:132
>2014-08-20 10:47:26.709 16556 AUDIT nova.compute.manager [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Detach volume 14bab350-200e-471d-be99-38d39d24b2fc from mountpoint /dev/vdb
>2014-08-20 10:47:26.727 16556 DEBUG nova.volume.cinder [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:47:26.729 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:47:26.792 16556 DEBUG urllib3.connectionpool [-] "GET /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/encryption HTTP/1.1" 200 209 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:47:26.796 16556 ERROR nova.compute.manager [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Failed to detach volume 14bab350-200e-471d-be99-38d39d24b2fc from /dev/vdb
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] Traceback (most recent call last):
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     encryption=encryption)
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1370, in detach_volume
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f]     raise exception.DiskNotFound(location=disk_dev)
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] DiskNotFound: No disk at vdb
>2014-08-20 10:47:26.796 16556 TRACE nova.compute.manager [instance: 542dbe02-fc5c-46b0-a620-f6b59f25e66f] 
>2014-08-20 10:47:26.797 16556 DEBUG nova.volume.cinder [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] Cinderclient connection created using URL: http://172.16.40.15:8776/v1/6e65bc9635274edab3013039804c683d cinderclient /usr/lib/python2.6/site-packages/nova/volume/cinder.py:93
>2014-08-20 10:47:26.798 16556 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.16.40.15
>2014-08-20 10:47:26.852 16556 DEBUG urllib3.connectionpool [-] "POST /v1/6e65bc9635274edab3013039804c683d/volumes/14bab350-200e-471d-be99-38d39d24b2fc/action HTTP/1.1" 202 0 _make_request /usr/lib/python2.6/site-packages/urllib3/connectionpool.py:295
>2014-08-20 10:47:26.926 16556 DEBUG nova.openstack.common.lockutils [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] Got semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:168
>2014-08-20 10:47:26.927 16556 DEBUG nova.openstack.common.lockutils [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] Got semaphore / lock "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:248
>2014-08-20 10:47:27.035 16556 DEBUG nova.openstack.common.lockutils [req-084098b2-28d7-47b6-b88a-8c6e6832e503 admin admin] Semaphore / lock released "update_usage" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:252
>2014-08-20 10:47:27.042 16556 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: No disk at vdb
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     payload)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     pass
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     e, sys.exc_info())
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     self._detach_volume(context, instance, bdm)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     self.volume_api.roll_detaching(context, volume_id)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     encryption=encryption)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1370, in detach_volume
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher     raise exception.DiskNotFound(location=disk_dev)
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher DiskNotFound: No disk at vdb
>2014-08-20 10:47:27.042 16556 TRACE oslo.messaging.rpc.dispatcher 
>2014-08-20 10:47:27.043 16556 ERROR oslo.messaging._drivers.common [-] Returning exception No disk at vdb to caller
>2014-08-20 10:47:27.043 16556 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 274, in decorated_function\n    pass\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 260, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 303, in decorated_function\n    e, sys.exc_info())\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 290, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4240, in detach_volume\n    self._detach_volume(context, instance, bdm)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4210, in _detach_volume\n    self.volume_api.roll_detaching(context, volume_id)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 4203, in _detach_volume\n    encryption=encryption)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1370, in detach_volume\n    raise exception.DiskNotFound(location=disk_dev)\n', 'DiskNotFound: No disk at vdb\n']

Actions: View

Attachments on bug 1132053: 928854 | 928856 | 928858