Delete while creating: HANDLE_INVALID

[Gabe Westmaas]

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)]

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.

[Johannes Erdfelt (johannes.erdfelt)]

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.

[Johannes Erdfelt (johannes.erdfelt)]

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.

[Openstack Gerrit (openstack-gerrit)]

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