OpenStack Compute (nova)

Attempting to resize a server with bad / inaccurate volumeAttachment information results in ERROR state

Bug #1398685 reported by Patrick Crews
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Expired
Undecided
Unassigned

Bug Description

This is related to another bug: https://bugs.launchpad.net/cinder/+bug/1398588/

If one attempts to resize a server with volume attachment information that is inaccurate / contradicts Cinder's data (eg it thinks a volume is attached that is not), it results in the server going into an unrecoverable ERROR state:

Fault

Message
    'NoneType' object has no attribute 'get'
Code
    500
Details
    File "/opt/stack/nova/nova/compute/manager.py", line 314, in decorated_function return function(self, context, *args, **kwargs) File "/opt/stack/nova/nova/compute/manager.py", line 3900, in finish_resize self._set_instance_error_state(context, instance) File "/opt/stack/nova/nova/openstack/common/excutils.py", line 82, in __exit__ six.reraise(self.type_, self.value, self.tb) File "/opt/stack/nova/nova/compute/manager.py", line 3888, in finish_resize disk_info, image) File "/opt/stack/nova/nova/compute/manager.py", line 3856, in _finish_resize old_instance_type, sys_meta) File "/opt/stack/nova/nova/openstack/common/excutils.py", line 82, in __exit__ six.reraise(self.type_, self.value, self.tb) File "/opt/stack/nova/nova/compute/manager.py", line 3851, in _finish_resize block_device_info, power_on) File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 5988, in finish_migration write_to_disk=True) File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4152, in _get_guest_xml context) File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3932, in _get_guest_config flavor): File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3483, in _get_guest_storage_config cfg = self._connect_volume(connection_info, info) File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1321, in _connect_volume driver_type = connection_info.get('driver_volume_type')

Tags: volumes
Patrick Crews (patrick-crews)
Changed in nova:
status: New → Confirmed
Patrick Crews (patrick-crews)
Changed in nova:
status: Confirmed → New
Patrick Crews (patrick-crews)
Changed in nova:
status: New → Confirmed
Joe Gordon (jogo)
Changed in nova:
importance: Undecided → Medium
tags: added: volumes
Revision history for this message
Patrick Crews (patrick-crews) wrote :
Download full text (7.1 KiB)

Full traceback from cpu logs:
157433:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
157434:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
157435:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher incoming.message))
157436:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
157437:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
157438:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
157439:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
157440:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
157441:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher payload)
157442:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/openstack/common/excutils.py", line 82, in __exit__
157443:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
157444:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
157445:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher return f(self, context, *args, **kw)
157446:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/compute/manager.py", line 298, in decorated_function
157447:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher pass
157448:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/openstack/common/excutils.py", line 82, in __exit__
157449:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
157450:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/compute/manager.py", line 284, in decorated_function
157451:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
157452:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/compute/manager.py", line 348, in decorated_function
157453:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs)
157454:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/compute/manager.py", line 272, in decorated_function
157455:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher migration.instance_uuid, exc_info=True)
157456:2014-12-10 10:21:13.980 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/nova/nova/openstack/common/excutils.py", line 82, in __exit__
157457:2014-12-10 10:21:13.980 TRACE oslo.messaging....

Read more...

Revision history for this message
Patrick Crews (patrick-crews) wrote :
Download full text (42.8 KiB)

trace of a request from the cpu logs:
screen-n-cpu.log:283824:2014-12-10 10:58:13.461 DEBUG nova.compute.manager [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] Stashing vm_state: active from (pid=21243) _prep_resize /opt/stack/nova/nova/compute/manager.py:3608
screen-n-cpu.log:283832:2014-12-10 10:58:13.659 DEBUG nova.openstack.common.lockutils [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] Created new semaphore "compute_resources" from (pid=21243) internal_lock /opt/stack/nova/nova/openstack/common/lockutils.py:206
screen-n-cpu.log:283833:2014-12-10 10:58:13.660 DEBUG nova.openstack.common.lockutils [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] Acquired semaphore "compute_resources" from (pid=21243) lock /opt/stack/nova/nova/openstack/common/lockutils.py:229
screen-n-cpu.log:283834:2014-12-10 10:58:13.660 DEBUG nova.openstack.common.lockutils [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] Got semaphore / lock "resize_claim" from (pid=21243) inner /opt/stack/nova/nova/openstack/common/lockutils.py:271
screen-n-cpu.log:283835:2014-12-10 10:58:13.660 DEBUG nova.compute.resource_tracker [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] Memory overhead for 4096 MB instance; 0 MB from (pid=21243) resize_claim /opt/stack/nova/nova/compute/resource_tracker.py:171
screen-n-cpu.log:283836:2014-12-10 10:58:13.662 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] Attempting claim: memory 4096 MB, disk 0 GB
screen-n-cpu.log:283837:2014-12-10 10:58:13.662 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] Total memory: 36198 MB, used: 7168.00 MB
screen-n-cpu.log:283838:2014-12-10 10:58:13.663 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] memory limit: 54297.00 MB, free: 47129.00 MB
screen-n-cpu.log:283839:2014-12-10 10:58:13.663 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] Total disk: 422 GB, used: 0.00 GB
screen-n-cpu.log:283840:2014-12-10 10:58:13.663 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] disk limit not specified, defaulting to unlimited
screen-n-cpu.log:283841:2014-12-10 10:58:13.676 DEBUG nova.compute.resources.vcpu [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] Total CPUs: 8 VCPUs, used: 9.00 VCPUs from (pid=21243) test /opt/stack/nova/nova/compute/resources/vcpu.py:51
screen-n-cpu.log:283842:2014-12-10 10:58:13.676 DEBUG nova.compute.resources.vcpu [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] CPUs limit not specified, defaulting to unlimited from (pid=21243) test /opt/stack/nova/nova/compute/resources/vcpu.py:55
screen-n-cpu.log:283843:2014-12-10 10:58:13.677 AUDIT nova.compute.claims [req-4cad855e-60c2-4ac6-ab20-078285564b5a demo demo] [instance: f564ef8d-02a4-4dcc-a222-24fb5303daae] Claim successful
screen-n-cpu.log:283844:2014-12-10 10:58:13.739 AUDIT nov...

Revision history for this message
jichenjc (jichenjc) wrote :

I have following logs which is similar to the issue you have
but I need to go back to see whether we can keep the instance status if there's something wrong
during resize process

Revision history for this message
jichenjc (jichenjc) wrote :
Download full text (3.7 KiB)

2014-12-23 00:33:19.018 ERROR nova.compute.manager [^[[01;36mreq-d09ffb44-cb79-4c92-9009-cd0032bd5689 ^[[00;36mdemo demo] ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] Setting instance vm_state to ERROR^[[00m
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00mTraceback (most recent call last):
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/opt/stack/nova/nova/compute/manager.py", line 6109, in _error_out_instance_on_exception
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m yield
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/opt/stack/nova/nova/compute/manager.py", line 3769, in resize_instance
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m self._terminate_volume_connections(context, instance, bdms)
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/opt/stack/nova/nova/compute/manager.py", line 3798, in _terminate_volume_connections
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m connector)
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/opt/stack/nova/nova/volume/cinder.py", line 168, in wrapper
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m res = method(self, ctx, volume_id, *args, **kwargs)
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/opt/stack/nova/nova/volume/cinder.py", line 343, in terminate_connection
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m connector)
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/usr/lib/python2.6/site-packages/cinderclient/v2/volumes.py", line 384, in terminate_connection
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m {'connector': connector})
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/usr/lib/python2.6/site-packages/cinderclient/v2/volumes.py", line 311, in _action
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m return self.api.client.post(url, body=body)
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m File "/usr/lib/python2.6/site-packages/cinderclient/client.py", line 305, in post
2014-12-23 00:33:19.018 TRACE nova.compute.manager ^[[01;35m[instance: 7a2242e6-95f6-481c-927c-c944d9b7e02c] ^[[00m return self._cs_request(url, 'POST', **kwargs)...

Read more...

Revision history for this message
Robert Collins (lifeless) wrote :

To save other folk digging - this happens because the invalid details are only discovered at the end of the migration.

Revision history for this message
Robert Collins (lifeless) wrote :

File "/opt/stack/nova/nova/compute/manager.py", line 3851, in _finish_resize
          block_device_info, power_on)
File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 5988, in finish_migration
          write_to_disk=True)
File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4152, in _get_guest_xml
          context)
File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3932, in _get_guest_config
          flavor):
File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3483, in _get_guest_storage_config
          cfg = self._connect_volume(connection_info, info)
File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 1321, in _connect_volume
          driver_type = connection_info.get('driver_volume_type')
AttributeError: 'NoneType' object has no attribute 'get'

Revision history for this message
Patrick Crews (patrick-crews) wrote :

I was seeing this in connection with https://bugs.launchpad.net/cinder/+bug/1398588, so this is likely invalid.
Will attempt to retest again on a fresh dev environment and will update both bugs with the results this week.

Dharini Chandrasekar (dharini-chandrasekar)
Changed in nova:
assignee: nobody → Dharini Chandrasekar (dharini-chandrasekar)
Dharini Chandrasekar (dharini-chandrasekar)
Changed in nova:
assignee: Dharini Chandrasekar (dharini-chandrasekar) → nobody
Revision history for this message
Markus Zoeller (markus_z) (mzoeller) wrote : Cleanup EOL bug report

This is an automated cleanup. This bug report has been closed because it
is older than 18 months and there is no open code change to fix this.
After this time it is unlikely that the circumstances which lead to
the observed issue can be reproduced.

If you can reproduce the bug, please:
* reopen the bug report (set to status "New")
* AND add the detailed steps to reproduce the issue (if applicable)
* AND leave a comment "CONFIRMED FOR: <RELEASE_NAME>"
  Only still supported release names are valid (LIBERTY, MITAKA, OCATA, NEWTON).
  Valid example: CONFIRMED FOR: LIBERTY

Changed in nova:
importance: Medium → Undecided
status: Confirmed → Expired
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.