Delay in re-establishing api session

[Sabari Murugesan]

When we make invoke_api call and the session is in-active, we check if the session is active multiple times and then create a new session. Even after creating a new session, we wait for the 10 seconds before re-trying. I believe we should optimize this to avoid the delay due to session in-activeness.

2016-08-02 10:54:14.654 DEBUG oslo_vmware.api [req-6764c93c-2bbe-40da-920f-9e99e1de71b9 d58d541e88924a3ab9e660514667107d 893f107283da4
1299c158026bb37441e] Waiting for function oslo_vmware.api._invoke_api to return. from (pid=16356) func /opt/vio/oslo.vmware/oslo_vmwar
e/api.py:122
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:791: InsecureRequestWarning: Unverified HTTPS reque
st is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.org/en/latest/security.html
  InsecureRequestWarning)
2016-08-02 10:54:14.942 WARNING suds.client [-] Web service reported a SOAP processing fault using an unexpected HTTP status code 200.
 Reporting as an internal server error.
2016-08-02 10:54:14.943 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/XMLSc
hema-instance" xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">
   <ns1:Body>
      <ns0:FindByInventoryPath>
         <ns0:_this type="SearchIndex">SearchIndex</ns0:_this>
         <ns0:inventoryPath>/dc_folder/Datacenter1/vm/74dba1ed-1140-4b2d-a1db-848d9b571892</ns0:inventoryPath>
      </ns0:FindByInventoryPath>
   </ns1:Body>
</SOAP-ENV:Envelope>
2016-08-02 10:54:14.943 DEBUG oslo_vmware.api [-] Checking if the current session: 5f427 is active. from (pid=16356) is_current_sessio
n_active /opt/vio/oslo.vmware/oslo_vmware/api.py:356
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:791: InsecureRequestWarning: Unverified HTTPS reque
st is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.org/en/latest/security.html
  InsecureRequestWarning)
2016-08-02 10:54:14.951 WARNING suds.client [-] Web service reported a SOAP processing fault using an unexpected HTTP status code 200.
 Reporting as an internal server error.
2016-08-02 10:54:14.951 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:SessionIsActive>
         <ns0:_this type="SessionManager">SessionManager</ns0:_this>
         <ns0:sessionID>5f427</ns0:sessionID>
         <ns0:userName>***</ns0:userName>
      </ns0:SessionIsActive>
   </ns1:Body>
</SOAP-ENV:Envelope>
2016-08-02 10:54:14.952 DEBUG oslo_vmware.api [-] Error: The session is not authenticated.
Cause: Server raised fault: 'The session is not authenticated.'
Faults: [NotAuthenticated]
Details: {'privilegeId': 'Sessions.ValidateSession', 'object': 'group-d1'} occurred while checking whether the current session: 5f427 is active. from (pid=16356) is_current_session_active /opt/vio/oslo.vmware/oslo_vmware/api.py:368
2016-08-02 10:54:14.953 DEBUG oslo_vmware.api [-] Current session: 5f427 is inactive; re-creating the session while invoking method VIM Object.FindByInventoryPath. from (pid=16356) _invoke_api /opt/vio/oslo.vmware/oslo_vmware/api.py:318
2016-08-02 10:54:14.953 DEBUG oslo_vmware.api [-] Waiting for function oslo_vmware.api._create_session to return. from (pid=16356) func /opt/vio/oslo.vmware/oslo_vmware/api.py:122
2016-08-02 10:54:14.953 DEBUG oslo_concurrency.lockutils [-] Lock "oslo_vmware_api_lock" acquired by "oslo_vmware.api._create_session" :: waited 0.000s from (pid=16356) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-08-02 10:54:14.954 DEBUG oslo_vmware.api [-] Checking if the current session: 5f427 is active. from (pid=16356) is_current_session_active /opt/vio/oslo.vmware/oslo_vmware/api.py:356
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:791: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.org/en/latest/security.html
  InsecureRequestWarning)
2016-08-02 10:54:14.962 WARNING suds.client [-] Web service reported a SOAP processing fault using an unexpected HTTP status code 200. Reporting as an internal server error.
2016-08-02 10:54:14.962 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:SessionIsActive>
         <ns0:_this type="SessionManager">SessionManager</ns0:_this>
         <ns0:sessionID>5f427</ns0:sessionID>
         <ns0:userName>***</ns0:userName>
      </ns0:SessionIsActive>
   </ns1:Body>
</SOAP-ENV:Envelope>
2016-08-02 10:54:14.963 DEBUG oslo_vmware.api [-] Error: The session is not authenticated.
Cause: Server raised fault: 'The session is not authenticated.'
Faults: [NotAuthenticated]
Details: {'privilegeId': 'Sessions.ValidateSession', 'object': 'group-d1'} occurred while checking whether the current session: 5f427 is active. from (pid=16356) is_current_session_active /opt/vio/oslo.vmware/oslo_vmware/api.py:368
2016-08-02 10:54:14.963 DEBUG oslo_vmware.api [-] Logging into host: 10.20.116.124. from (pid=16356) _create_session /opt/vio/oslo.vmware/oslo_vmware/api.py:233
/usr/local/lib/python2.7/dist-packages/requests/packages/urllib3/connectionpool.py:791: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.org/en/latest/security.html
  InsecureRequestWarning)
2016-08-02 10:54:15.178 INFO oslo_vmware.api [-] Successfully established new session; session ID is afcae.
2016-08-02 10:54:15.178 DEBUG oslo_concurrency.lockutils [-] Lock "oslo_vmware_api_lock" released by "oslo_vmware.api._create_session" :: held 0.225s from (pid=16356) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-08-02 10:54:15.179 WARNING oslo_vmware.api [-] Exception which is in the suggested list of exceptions occurred while invoking function: oslo_vmware.api._invoke_api.
2016-08-02 10:54:15.179 TRACE oslo_vmware.api Traceback (most recent call last):
2016-08-02 10:54:15.179 TRACE oslo_vmware.api File "/opt/vio/oslo.vmware/oslo_vmware/api.py", line 96, in _func
2016-08-02 10:54:15.179 TRACE oslo_vmware.api result = f(*args, **kwargs)
2016-08-02 10:54:15.179 TRACE oslo_vmware.api File "/opt/vio/oslo.vmware/oslo_vmware/api.py", line 321, in _invoke_api
2016-08-02 10:54:15.179 TRACE oslo_vmware.api excep)
2016-08-02 10:54:15.179 TRACE oslo_vmware.api VimConnectionException: Current session: 5f427 is inactive; re-creating the session while invoking method VIM Object.FindByInventoryPath.
2016-08-02 10:54:15.179 TRACE oslo_vmware.api Cause: The session is not authenticated.
2016-08-02 10:54:15.179 TRACE oslo_vmware.api Cause: Server raised fault: 'The session is not authenticated.'
2016-08-02 10:54:15.179 TRACE oslo_vmware.api Faults: [NotAuthenticated]
2016-08-02 10:54:15.179 TRACE oslo_vmware.api Details: {'privilegeId': 'System.View', 'object': 'group-d1'}
2016-08-02 10:54:15.179 TRACE oslo_vmware.api
2016-08-02 10:54:15.180 DEBUG oslo_vmware.common.loopingcall [-] Dynamic looping call sleeping for 10.00 seconds from (pid=16356) _inner /opt/vio/oslo.vmware/oslo_vmware/common/loopingcall.py:130

[Sabari Murugesan (smurugesan)]

http://paste.openstack.org/show/545746/ for more clarity.

[Ben Nemec (bnemec)]

Can you confirm that this is still a problem in the current version? Thanks.