OpenStack Compute (Nova)

Delete while creating: HANDLE_INVALID

Reported by Gabe Westmaas on 2011-11-29
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Medium
Johannes Erdfelt

Bug Description

There appears to be a race condition when creating a server and then quickly deleting a server in using Xen.

The trace is an example of a result of this race condition, but the general problem of what to do when an instance has not finished booting initially but we receive a delete should be addressed.

2011-11-29 18:12:26,422 WARNING nova.virt.xenapi [d999221b-b265-44f3-aba5-2de28a346564 None None] Task [Async.host.call_plugin] OpaqueRef:ddf715fd-05fe-082c-1481-4193f9cee736 status: failure ['XENAPI_PLUGIN_EXCEPTION', 'version', 'XenstoreError', "cmd: ['xenstore-rm', '/local/domain/270/data/host/5a7cafc3-8ce0-4b19-baac-7248e859b02e']; returncode: 1; stderr: xenstore-rm: could not remove path /local/domain/270/data/host/5a7cafc3-8ce0-4b19-baac-7248e859b02e\n; stdout: "]
2011-11-29 18:12:26,422 ERROR nova.virt.xenapi.vmops [-] The call to version returned an error: ['XENAPI_PLUGIN_EXCEPTION', 'version', 'XenstoreError', "cmd: ['xenstore-rm', '/local/domain/270/data/host/5a7cafc3-8ce0-4b19-baac-7248e859b02e']; returncode: 1; stderr: xenstore-rm: could not remove path /local/domain/270/data/host/5a7cafc3-8ce0-4b19-baac-7248e859b02e\n; stdout: "]. VM id=2232; args={'path': '', 'dom_id': '270', 'id': '5a7cafc3-8ce0-4b19-baac-7248e859b02e'}
2011-11-29 18:12:26,423 ERROR nova.virt.xenapi.vmops [-] Failed to query agent version: {'message': '; stdout: ', 'returncode': 'error'}
2011-11-29 18:12:26,472 WARNING nova.virt.xenapi.vmops [-] ['HANDLE_INVALID', 'VM', 'OpaqueRef:18a07139-2918-7551-ea50-508585bde4bc']
2011-11-29 18:12:26,472 ERROR nova.virt.xenapi.vmops [-] Instance instance-b79dce45-4ab0-4722-8eff-d97d4d69ee75: failed to boot
(nova.virt.xenapi.vmops): TRACE: Traceback (most recent call last):
(nova.virt.xenapi.vmops): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/xenapi/vmops.py", line 499, in _wait_for_boot
(nova.virt.xenapi.vmops): TRACE: _check_agent_version()
(nova.virt.xenapi.vmops): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/xenapi/vmops.py", line 440, in _check_agent_version
(nova.virt.xenapi.vmops): TRACE: version = self.get_agent_version(instance)
(nova.virt.xenapi.vmops): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/xenapi/vmops.py", line 852, in get_agent_version
(nova.virt.xenapi.vmops): TRACE: vm_rec = self._session.call_xenapi("VM.get_record", vm_ref)
(nova.virt.xenapi.vmops): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/xenapi_conn.py", line 491, in call_xenapi
(nova.virt.xenapi.vmops): TRACE: return tpool.execute(f, *args)
(nova.virt.xenapi.vmops): TRACE: File "/usr/lib/pymodules/python2.6/eventlet/tpool.py", line 76, in tworker
(nova.virt.xenapi.vmops): TRACE: rv = meth(*args,**kwargs)
(nova.virt.xenapi.vmops): TRACE: File "/usr/local/lib/python2.6/dist-packages/XenAPI.py", line 229, in __call__
(nova.virt.xenapi.vmops): TRACE: return self.__send(self.__name, args)
(nova.virt.xenapi.vmops): TRACE: File "/usr/local/lib/python2.6/dist-packages/XenAPI.py", line 133, in xenapi_request
(nova.virt.xenapi.vmops): TRACE: result = _parse_result(getattr(self, methodname)(*full_params))
(nova.virt.xenapi.vmops): TRACE: File "/usr/local/lib/python2.6/dist-packages/XenAPI.py", line 203, in _parse_result
(nova.virt.xenapi.vmops): TRACE: raise Failure(result['ErrorDescription'])
(nova.virt.xenapi.vmops): TRACE: Failure: ['HANDLE_INVALID', 'VM', 'OpaqueRef:18a07139-2918-7551-ea50-508585bde4bc']
(nova.virt.xenapi.vmops): TRACE:

Gabe Westmaas (westmaas) wrote :

Note further that create/delete isn't the only race condition, anything that interacts with Xen directly may have this same issue: pause/unpause, etc.

Thierry Carrez (ttx) on 2011-12-02
Changed in nova:
importance: Undecided → Medium
status: New → Confirmed
Thierry Carrez (ttx) on 2011-12-02
summary: - HANDLE_INVALID when creating and deleting a server
+ Delete while creating: HANDLE_INVALID
tags: added: concurrency

Just for reference, this is a similar problem to https://bugs.launchpad.net/nova/+bug/887708

But it appears to be caused by a slightly different problem.

I don't think this is a duplicate of bug #893582. This bug deals with deleting a different VM from the one being created. Bug #893582 deals with deleting the same VM as the one being created.

I think they have different failure scenarios and should be separate bugs.

Changed in nova:
assignee: nobody → Johannes Erdfelt (johannes.erdfelt)
Jay Pipes (jaypipes) on 2011-12-13
Changed in nova:
status: Confirmed → In Progress

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

 status fixcommitted
 done

commit d58c2d2bae97c9193e54056405a8f851051fdada
Author: Johannes Erdfelt <email address hidden>
Date: Mon Dec 12 18:01:54 2011 +0000

    Make XenAPI agent configuration synchronous

    Fixes bug 897887

    Much of the XenAPI agent configuration happens asynchronously from the
    spawn process. This allows the instance to go ACTIVE state earlier and
    leaves the possibility of a race with delete open. This makes the
    steps synchronous, ensuring the process only goes to ACTIVE after the
    configuration is done.

    Change-Id: I294b595128979e153c797d9e610b66bc76f47666

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2012-01-25
Changed in nova:
milestone: none → essex-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2012-04-05
Changed in nova:
milestone: essex-3 → 2012.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers