yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1079745] Re: Essex 2012.1.3 : Error deleting instance with 2 Nova Volumes attached

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Sean Dague <sean@xxxxxxxxx>
Date: Fri, 19 Sep 2014 10:57:27 -0000
Reply-to: Bug 1079745 <1079745@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** No longer affects: nova/essex

-- 
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/1079745

Title:
  Essex 2012.1.3 : Error deleting instance with 2 Nova Volumes attached

Status in OpenStack Compute (Nova):
  Invalid
Status in “nova” package in Ubuntu:
  Fix Released
Status in “nova” source package in Precise:
  Fix Released

Bug description:
  Hi, we are using "Essex 2012.1.3" with Ubuntu 12.04, and when we
  delete an instance that has 2 nova volumes attached, we see in the
  compute logs, that it tries to detach the same volume twice, stacking
  because of iscsadm commnad, leaving both nova volumes in "in-use"
  state, and the instance in "deleting" task, and shutoff state.

  Here's the volume-list command for the volumes after the "delete"
  command.

  +-----+----------------+--------------+------+-------------+--------------------------------------+
  | ID  | Status         | Display Name | Size | Volume Type | Attached to                          |
  +-----+----------------+--------------+------+-------------+--------------------------------------+
  | 306 | in-use         | ev-00000160  | 8    | None        | 6e97906c-6122-408a-b151-7d23aaae089b |
  | 311 | in-use         | ev-00000161  | 10   | None        | 6e97906c-6122-408a-b151-7d23aaae089b |

  Here's the "show" command for the vm :

  +-------------------------------------+-------------------------------------------------------------+
  | Property                            | Value                                                       |
  +-------------------------------------+-------------------------------------------------------------+
  | OS-DCF:diskConfig                   | MANUAL                                                      |
  | OS-EXT-SRV-ATTR:host                | DC2-r9-23vms                                                |
  | OS-EXT-SRV-ATTR:hypervisor_hostname | None                                                        |
  | OS-EXT-SRV-ATTR:instance_name       | instance-000003f8                                           |
  | OS-EXT-STS:power_state              | 0                                                           |
  | OS-EXT-STS:task_state               | deleting                                                    |
  | OS-EXT-STS:vm_state                 | shutoff                                                     |
  | accessIPv4                          |                                                             |
  | accessIPv6                          |                                                             |
  | config_drive                        |                                                             |
  | created                             | 2012-11-15T18:13:16Z                                        |
  | flavor                              | gz.micro (1)                                                |
  | hostId                              | 1251f2dc1db48c4c0692d5dd7152312461e83536014d81da5c8c8a27    |
  | id                                  | 6e97906c-6122-408a-b151-7d23aaae089b                        |
  | image                               | ami_PRECISE_20120927 (f76cb3f7-7e83-4fb1-a189-611f6a2e9eef) |
  | key_name                            |                                                             |
  | metadata                            | {u'region': u'DC2_r9', u'name': u'e-000004dc'}              |
  | name                                | e-000004dc                                                  |
  | private network                     | 172.16.76.218                                               |
  | status                              | SHUTOFF                                                     |
  | tenant_id                           | 7ca5bf73c54f4647b689b01c2a4f0bde                            |
  | updated                             | 2012-11-16T14:56:58Z                                        |
  | user_id                             | 5744a1b442e8400ca3da9e85845045e4                            |
  +-------------------------------------+-------------------------------------------------------------+

  And here are the nova-compute.log for the operation that stacks:

  2012-11-16 09:46:33 DEBUG nova.rpc.amqp [-] received {u'_context_roles': [u'asoc_arquitectura'], u'_context_request_id': u'req-ed637bc2-9e77-4564-bb27-27658cc699db', u'_context_read_deleted': u'no', u'args': {u'instance_uuid': u'6e97906c-6122-408a-b151-7d23aaae089b'}, u'_context_auth_token': '<SANITIZED>', u'_context_is_admin': False, u'_context_project_id': u'7ca5bf73c54f4647b689b01c2a4f0bde', u'_context_timestamp': u'2012-11-16T14:46:06.546864', u'_context_user_id': u'5744a1b442e8400ca3da9e85845045e4', u'method': u'terminate_instance', u'_context_remote_address': u'172.16.150.76'} from (pid=25044) _safe_log /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/common.py:160
  2012-11-16 09:46:33 DEBUG nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] unpacked context: {'user_id': u'5744a1b442e8400ca3da9e85845045e4', 'roles': [u'asoc_arquitectura'], 'timestamp': '2012-11-16T14:46:06.546864', 'auth_token': '<SANITIZED>', 'remote_address': u'172.16.150.76', 'is_admin': False, 'request_id': u'req-ed637bc2-9e77-4564-bb27-27658cc699db', 'project_id': u'7ca5bf73c54f4647b689b01c2a4f0bde', 'read_deleted': u'no'} from (pid=25044) _safe_log /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/common.py:160
  2012-11-16 09:46:33 INFO nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] check_instance_lock: decorating: |<function terminate_instance at 0x1d56de8>|
  2012-11-16 09:46:33 INFO nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] check_instance_lock: arguments: |<nova.compute.manager.ComputeManager object at 0x7f6da2a1f610>| |<nova.rpc.amqp.RpcContext object at 0x407d5d0>| |6e97906c-6122-408a-b151-7d23aaae089b|
  2012-11-16 09:46:33 DEBUG nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] instance 6e97906c-6122-408a-b151-7d23aaae089b: getting locked state from (pid=25044) get_lock /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py:1626
  2012-11-16 09:46:33 INFO nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] check_instance_lock: locked: |False|
  2012-11-16 09:46:33 INFO nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] check_instance_lock: admin: |False|
  2012-11-16 09:46:33 INFO nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] check_instance_lock: executing: |<function terminate_instance at 0x1d56de8>|
  2012-11-16 09:46:33 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Attempting to grab semaphore "6e97906c-6122-408a-b151-7d23aaae089b" for method "do_terminate_instance"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:927
  2012-11-16 09:46:33 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Got semaphore "6e97906c-6122-408a-b151-7d23aaae089b" for method "do_terminate_instance"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:931
  2012-11-16 09:46:33 AUDIT nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] [instance: 6e97906c-6122-408a-b151-7d23aaae089b] Terminating instance
  2012-11-16 09:46:33 DEBUG nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Making asynchronous call on network ... from (pid=25044) multicall /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/amqp.py:326
  2012-11-16 09:46:33 DEBUG nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] MSG_ID is a60c1d4fb94344b3a8a4ded3ff83ed86 from (pid=25044) multicall /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/amqp.py:329
  2012-11-16 09:46:33 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000003f8/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:33 DEBUG nova.virt.libvirt.connection [-] skipping None since it looks like volume from (pid=25044) get_instance_disk_info /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/connection.py:2287
  2012-11-16 09:46:33 DEBUG nova.virt.libvirt.connection [-] skipping None since it looks like volume from (pid=25044) get_instance_disk_info /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/connection.py:2287
  2012-11-16 09:46:34 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000385/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:34 DEBUG nova.compute.manager [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] [instance: 6e97906c-6122-408a-b151-7d23aaae089b] Deallocating network for instance from (pid=25044) _deallocate_network /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py:641
  2012-11-16 09:46:34 DEBUG nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Making asynchronous call on network ... from (pid=25044) multicall /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/amqp.py:326
  2012-11-16 09:46:34 DEBUG nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] MSG_ID is 025d818087da436697458c520195300f from (pid=25044) multicall /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/amqp.py:329
  2012-11-16 09:46:34 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000385/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:35 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000308/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:35 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000308/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:36 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000009/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:38 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Attempting to grab semaphore "iptables" for method "apply"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:927
  2012-11-16 09:46:38 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Got semaphore "iptables" for method "apply"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:931
  2012-11-16 09:46:38 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Attempting to grab file lock "iptables" for method "apply"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:935
  2012-11-16 09:46:38 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Got file lock "iptables" for method "apply"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:942
  2012-11-16 09:46:38 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iptables-save -t filter from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:39 INFO nova.virt.libvirt.connection [-] [instance: 6e97906c-6122-408a-b151-7d23aaae089b] Instance destroyed successfully.
  2012-11-16 09:46:39 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000009/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:39 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iptables-restore from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:40 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000002fd/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:40 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000002fd/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:40 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iptables-save -t nat from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:41 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000161/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:41 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iptables-restore from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:41 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-00000161/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:42 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000000b9/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:42 DEBUG nova.network.linux_net [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] IPTablesManager.apply completed with success from (pid=25044) apply /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/network/linux_net.py:335
  2012-11-16 09:46:44 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Attempting to grab semaphore "connect_volume" for method "disconnect_volume"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:927
  2012-11-16 09:46:44 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Got semaphore "connect_volume" for method "disconnect_volume"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:931
  2012-11-16 09:46:53 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iscsiadm -m node -T iqn.1992-08.com.netapp:sn.1574861693 -p 10.1.1.160:3260 --op update -n node.startup -v manual from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:54 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000000b9/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:54 DEBUG nova.virt.libvirt.volume [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] iscsiadm ('--op', 'update', '-n', 'node.startup', '-v', 'manual'): stdout= stderr= from (pid=25044) _run_iscsiadm /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py:112
  2012-11-16 09:46:54 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iscsiadm -m node -T iqn.1992-08.com.netapp:sn.1574861693 -p 10.1.1.160:3260 --logout from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:55 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000003fc/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:55 DEBUG nova.virt.libvirt.volume [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] iscsiadm ('--logout',): stdout=Logging out of session [sid: 4, target: iqn.1992-08.com.netapp:sn.1574861693, portal: 10.1.1.160,3260]
  Logout of [sid: 4, target: iqn.1992-08.com.netapp:sn.1574861693, portal: 10.1.1.160,3260]: successful
   stderr= from (pid=25044) _run_iscsiadm /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py:112
  2012-11-16 09:46:55 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iscsiadm -m node -T iqn.1992-08.com.netapp:sn.1574861693 -p 10.1.1.160:3260 --op delete from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:55 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-000003fc/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:56 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-0000010d/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:46:56 DEBUG nova.virt.libvirt.volume [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] iscsiadm ('--op', 'delete'): stdout= stderr= from (pid=25044) _run_iscsiadm /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py:112
  2012-11-16 09:46:56 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Attempting to grab semaphore "connect_volume" for method "disconnect_volume"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:927
  2012-11-16 09:46:56 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Got semaphore "connect_volume" for method "disconnect_volume"... from (pid=25044) inner /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:931
  2012-11-16 09:47:06 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Running cmd (subprocess): sudo nova-rootwrap iscsiadm -m node -T iqn.1992-08.com.netapp:sn.1574861693 -p 10.1.1.160:3260 --op update -n node.startup -v manual from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:47:06 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img info /var/lib/nova/instances/instance-0000010d/disk from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:219
  2012-11-16 09:47:06 DEBUG nova.utils [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Result was 255 from (pid=25044) execute /usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py:235
  2012-11-16 09:47:06 ERROR nova.rpc.amqp [req-ed637bc2-9e77-4564-bb27-27658cc699db 5744a1b442e8400ca3da9e85845045e4 7ca5bf73c54f4647b689b01c2a4f0bde] Exception during message handling
  2012-11-16 09:47:06 TRACE nova.rpc.amqp Traceback (most recent call last):
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/rpc/amqp.py", line 253, in _process_data
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     rval = node_func(context=ctxt, **node_args)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/exception.py", line 114, in wrapped
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     return f(*args, **kw)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 159, in decorated_function
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     function(self, context, instance_uuid, *args, **kwargs)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 183, in decorated_function
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     sys.exc_info())
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     self.gen.next()
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 177, in decorated_function
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     return function(self, context, instance_uuid, *args, **kwargs)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 772, in terminate_instance
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     do_terminate_instance()
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py", line 945, in inner
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     retval = f(*args, **kwargs)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 765, in do_terminate_instance
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     self._delete_instance(context, instance)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 743, in _delete_instance
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     self._shutdown_instance(context, instance, 'Terminating')
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/compute/manager.py", line 712, in _shutdown_instance
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     block_device_info)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/connection.py", line 487, in destroy
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     cleanup=True)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/connection.py", line 479, in _destroy
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     mount_device)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/connection.py", line 525, in volume_driver_method
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     return method(connection_info, *args, **kwargs)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py", line 945, in inner
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     retval = f(*args, **kwargs)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py", line 204, in disconnect_volume
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     self._iscsiadm_update(iscsi_properties, "node.startup", "manual")
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py", line 118, in _iscsiadm_update
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     return self._run_iscsiadm(iscsi_properties, iscsi_command)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/virt/libvirt/volume.py", line 110, in _run_iscsiadm
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     check_exit_code=check_exit_code)
  2012-11-16 09:47:06 TRACE nova.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/nova-2012.1.3-py2.7.egg/nova/utils.py", line 242, in execute
  2012-11-16 09:47:06 TRACE nova.rpc.amqp     cmd=' '.join(cmd))
  2012-11-16 09:47:06 TRACE nova.rpc.amqp ProcessExecutionError: Unexpected error while running command.
  2012-11-16 09:47:06 TRACE nova.rpc.amqp Command: sudo nova-rootwrap iscsiadm -m node -T iqn.1992-08.com.netapp:sn.1574861693 -p 10.1.1.160:3260 --op update -n node.startup -v manual
  2012-11-16 09:47:06 TRACE nova.rpc.amqp Exit code: 255
  2012-11-16 09:47:06 TRACE nova.rpc.amqp Stdout: ''
  2012-11-16 09:47:06 TRACE nova.rpc.amqp Stderr: 'iscsiadm: no records found!\n'
  2012-11-16 09:47:06 TRACE nova.rpc.amqp

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