OpenStack Compute (nova)

resize instance doesn't use connection_info from initialize_connection

Bug #1076801 reported by clayg
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Rick Harris
OpenStack Compute (nova) 2013.1 "grizzly"

Bug Description

During finish_resize the computer manager calls volume_api.initialize_connection but doesn't use the return value.

If the connection info changes (e.g. new iqn or chap) the new resized instance can't attach the volumes and goes to error:

2012-11-08 22:00:08 DEBUG nova.openstack.common.lockutils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Got semaphore "connect_volume
" for method "connect_volume"... from (pid=13925) inner /opt/stack/nova/nova/openstack/common/lockutils.py:186
2012-11-08 22:00:08 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/
nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p
 10.127.0.162:3260 from (pid=13925) execute /opt/stack/nova/nova/utils.py:181
2012-11-08 22:00:08 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Result was 255 from (pid=13925) execute /opt/stack
/nova/nova/utils.py:197
2012-11-08 22:00:08 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/
nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p
 10.127.0.162:3260 --op new from (pid=13925) execute /opt/stack/nova/nova/utils.py:181
2012-11-08 22:00:08 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Result was 0 from (pid=13925) execute /opt/stack/n
ova/nova/utils.py:197
2012-11-08 22:00:08 DEBUG nova.virt.libvirt.volume [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] iscsiadm ('--op', 'new'): stdout=New
 iSCSI node [tcp:[hw=,ip=,net_if=,iscsi_if=default] 10.127.0.162,3260,-1 iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24
056-fabf-4721-b4ae-199eaac665dd] added
 stderr= from (pid=13925) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:119
2012-11-08 22:00:08 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/
nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p
 10.127.0.162:3260 --login from (pid=13925) execute /opt/stack/nova/nova/utils.py:181
2012-11-08 22:00:09 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Result was 255 from (pid=13925) execute /opt/stack
/nova/nova/utils.py:197
2012-11-08 22:00:09 DEBUG nova.virt.libvirt.volume [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] iscsiadm ('--login',): stdout=Loggin
g in to [iface: default, target: iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd, portal:
 10.127.0.162,3260]
 stderr=iscsiadm: Could not login to [iface: default, target: iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-47
21-b4ae-199eaac665dd, portal: 10.127.0.162,3260]:
iscsiadm: initiator reported error (19 - encountered non-retryable iSCSI login failure)
 from (pid=13925) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:119
2012-11-08 22:00:09 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/
nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p
 10.127.0.162:3260 --op update -n node.startup -v automatic from (pid=13925) execute /opt/stack/nova/nova/utils.py:181
2012-11-08 22:00:09 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Result was 0 from (pid=13925) execute /opt/stack/n
ova/nova/utils.py:197
2012-11-08 22:00:09 DEBUG nova.virt.libvirt.volume [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] iscsiadm ('--op', 'update', '-n', 'n
ode.startup', '-v', 'automatic'): stdout= stderr= from (pid=13925) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:119
2012-11-08 22:00:09 WARNING nova.virt.libvirt.volume [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] ISCSI volume not yet found at: vdb
. Will rescan & retry. Try number: 0
2012-11-08 22:00:09 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/
nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p
 10.127.0.162:3260 --rescan from (pid=13925) execute /opt/stack/nova/nova/utils.py:181
2012-11-08 22:00:09 DEBUG nova.utils [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] Result was 255 from (pid=13925) execute /opt/stack/nova/nova/utils.py:197
2012-11-08 22:00:09 ERROR nova.compute.manager [req-574278b6-3610-4657-a7b1-3f6897d46b0a admin demo] [instance: 87b81085-6caa-46c8-9e20-d36b4ae509d9] Unexpected error while running command.
Command: sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p 10.127.0.162:3260 --rescan
Exit code: 255
Stdout: ''
Stderr: 'iscsiadm: No portal found.\n'. Setting instance vm_state to ERROR

2012-11-08 22:00:10 ERROR nova.openstack.common.rpc.amqp [-] Exception during message handling
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 276, in _process_da
ta
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispa
tch
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 115, in wrapped
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 90, in wrapped
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 175, in decorated_function
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp pass
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 161, in decorated_function
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 202, in decorated_function
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp kwargs['instance']['uuid'], e, sys.exc_info())
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 190, in decorated_function
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1911, in finish_resize
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self._set_instance_error_state(context, instance['uuid'])
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1899, in finish_resize
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp disk_info, image)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/compute/manager.py", line 1866, in _finish_resize
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp block_device_info)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 115, in wrapped
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp temp_level, payload)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self.gen.next()
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/exception.py", line 90, in wrapped
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return f(*args, **kw)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2886, in finish_migration
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp block_device_info=block_device_info)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1833, in to_xml
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp rescue, block_device_info)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1787, in get_guest_config
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp root_device):
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1656, in get_guest_storage_config
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp mount_device)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 629, in volume_driver_method
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp return method(connection_info, *args, **kwargs)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/openstack/common/lockutils.py", line 229, in inner
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp retval = f(*args, **kwargs)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/volume.py", line 183, in connect_volume
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp self._run_iscsiadm(iscsi_properties, ("--rescan",))
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/virt/libvirt/volume.py", line 117, in _run_iscsiadm
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp check_exit_code=check_exit_code)
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp File "/opt/stack/nova/nova/utils.py", line 204, in execute
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp cmd=' '.join(cmd))
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp ProcessExecutionError: Unexpected error while running command.
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp Command: sudo nova-rootwrap /etc/nova/rootwrap.conf iscsiadm -m node -T iqn.2010-11.com.rackspace:5ae88a6d-ba7a-4dd0-a1c1-d770395612a0.d2f24056-fabf-4721-b4ae-199eaac665dd -p 10.127.0.162:3260 --rescan
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp Exit code: 255
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp Stdout: ''
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp Stderr: 'iscsiadm: No portal found.\n'
2012-11-08 22:00:10 TRACE nova.openstack.common.rpc.amqp

Revision history for this message
clayg (clay-gerrard) wrote :
Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :

Can you please submit this through gerrit?

http://wiki.openstack.org/HowToContribute
http://wiki.openstack.org/GerritWorkflow

Davanum Srinivas (DIMS) (dims-v)
tags: added: low-hanging-fruit
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/15796

Changed in nova:
assignee: nobody → clayg (clay-gerrard)
status: New → In Progress
Revision history for this message
clayg (clay-gerrard) wrote :

So "with volumes" doesn't get hit much in nova.tests.compute.test_compute.ComputeTestCase

I managed to get in test_finish_resize_with_volumes:

https://review.openstack.org/#/c/15796/

But I found that pre_live_migration, and finish_revert_resize do the same thing.

Vish Ishaya (vishvananda)
tags: added: folsom-backport-potential
Vish Ishaya (vishvananda)
Changed in nova:
importance: Undecided → Medium
Rick Harris (rconradharris)
Changed in nova:
assignee: clayg (clay-gerrard) → Rick Harris (rconradharris)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

Fix proposed to branch: master
Review: https://review.openstack.org/21921

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/21921
Committed: http://github.com/openstack/nova/commit/befa4a61b03cd589ab9a616d3b5c265d8b17f524
Submitter: Jenkins
Branch: master

commit befa4a61b03cd589ab9a616d3b5c265d8b17f524
Author: Clay Gerrard <email address hidden>
Date: Fri Nov 9 17:13:20 2012 -0600

    Use connection_info on resize

    During finish_migration the manager calls initialize_connection but doesn't
    update the block_device_mapping with the (potentially new) connection_info
    returned.

    This can cause the bdm to get out of sync, the volume to fail to attach, and
    the resize to fail.

    Fixes bug #1076801

    Change-Id: Ie49ccd2138905e178843b375a9b16c3fe572d1db

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in nova:
milestone: none → grizzly-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: grizzly-3 → 2013.1
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.