vmware: "Not authenticated error occurred " on creation volume from existing volume

[satyadev svn]

1) cinder create --name vol1 1
2) cinder create --source-volid 749c9cfd-e969-4199-a090-87daff1a9d54 --display-name vo2 1 [here volume created but status : error]
+-------------------+--------------------------------------+
| Property | Value |
+-------------------+--------------------------------------+
| attachments | [] |
| availability_zone | nova |
| bootable | false |
| created_at | 2014-02-25T12:35:43.000000 |
| description | None |
| id | d55009de-0454-48a8-b73d-01f65c071b6c |
| metadata | {} |
| name | fastvol_clone1 |
| size | 1 |
| snapshot_id | None |
| source_volid | 749c9cfd-e969-4199-a090-87daff1a9d54 |
| status | error |
| user_id | bb6690d82af84ae4b7152498088b517f |
| volume_type | fast_clone |
+-------------------+--------------------------------------+

3) if you try to delete above created volume - volume not getting deleted and volume status continuously say "Error in deleting"

c-vol log : at step2

2014-02-26 10:34:09.395 ERROR cinder.volume.drivers.vmware.api [-] Not authenticated error occurred. Will create session and try API call again: Error(s): NotAuthenticated occurred in the cal
l to RetrievePropertiesEx..
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api Traceback (most recent call last):
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 194, in _invoke_api
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api return api_method(*args, **kwargs)
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api File "/opt/stack/cinder/cinder/volume/drivers/vmware/vim_util.py", line 212, in get_objects
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api options=options)
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api File "/opt/stack/cinder/cinder/volume/drivers/vmware/vim.py", line 174, in vim_request_handler
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api retrieve_properties_ex_fault_checker(response)
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api File "/opt/stack/cinder/cinder/volume/drivers/vmware/vim.py", line 153, in retrieve_properties_ex_fault_checker
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api exc_msg_list)
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api VimFaultException: Error(s): NotAuthenticated occurred in the call to RetrievePropertiesEx.
2014-02-26 10:34:09.395 TRACE cinder.volume.drivers.vmware.api
2014-02-26 10:34:09.611 ERROR suds.client [-] <?xml version="1.0" encoding="UTF-8"?>
<SOAP-ENV:Envelope xmlns:ns0="urn:vim25" xmlns:ns1="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:SOAP-ENV="http://schemas.xmlsoap.org
/soap/envelope/">
   <ns1:Body>
      <ns0:Login>
         <ns0:_this type="SessionManager">SessionManager</ns0:_this>
         <ns0:userName>root</ns0:userName>
         <ns0:password>vmware</ns0:password>
      </ns0:Login>
   </ns1:Body>
</SOAP-ENV:Envelope>
2014-02-26 10:34:09.613 ERROR cinder.openstack.common.loopingcall [-] in dynamic looping call
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall Traceback (most recent call last):
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall File "/opt/stack/cinder/cinder/openstack/common/loopingcall.py", line 123, in _inner
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall idle = self.f(*self.args, **self.kw)
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 83, in _func
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall raise excep
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall VimFaultException: Server raised fault: 'Cannot complete login due to an incorrect user name or password.'
2014-02-26 10:34:09.613 TRACE cinder.openstack.common.loopingcall

[Kanagaraj Manickam (kanagaraj-manickam)]

By looking at the exception stack, it says:
Server raised fault: 'Cannot complete login due to an incorrect user name or password.'

This is an clear exception message from the ESX side, so this defect occured due to the environment, not by the code, i believe.

[Subbu (subramanian-neelakantan)]

This is occurring though the username/password used to connect is correct. Interestingly the connection works for the first time and fails subsequently.

From analysing the logs I think this is the problem. Here we clone a volume and then delete it. For both these operations the backing does not exist. So we get an empty response from vim api call when fetching the backing. Incidentally for a not authenticated session too we get an empty response. Since we cannot differentiate between a valid empty response and a not authenticated scenario we just recreate the session and invoke the vim api once more before accepting the empty response. This is causing two consequent login attempts from our driver - one during clone and another during delete. So the assumption is that VC does not like consequent logins and is throwing an exception in this case. I validated this theory by trying to delete the cloned volume after waiting for some time (more than 10 mins), and the cloned volume was deleted successfully.

Note that there is a fix for this in the oslo.vmware library which checks for the an active session before retry.

[OpenStack Infra (hudson-openstack)]

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

[Gary Kotton (garyk)]

It would be great if this fix could make the icehouse release. It is currently blocking https://review.openstack.org/#/c/80284/ (the reason is the problem occurs when running minesweeper).
Thanks
Gary

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/81517
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=7ca4bea7e3d8688c847bdbcfe3e60900c61c297c
Submitter: Jenkins
Branch: master

commit 7ca4bea7e3d8688c847bdbcfe3e60900c61c297c
Author: Vipin Balachandran <email address hidden>
Date: Wed Mar 19 17:42:56 2014 +0530

    vmware: Use SessionIsActive to find stale session

    An API invocation with a stale session returns an empty response. In order
    to distinguish it from an API returning valid empty response, the session
    is recreated and the API is retried. If an empty response is received even
    after the retry, it can be assumed that the API response is actually empty.
    But this behavior results in authentication error from the VMware server
    when there is an active session and the API response is actually empty.
    This change fix this behavior by using the SessionIsActive check to
    identify stale session.

    Change-Id: I6ddc4028bc5319cd22006de0590c13d6868c3494
    Closes-Bug: #1284979

[satyadev svn (svnsatya)]

Verified working fine on latest change set.