Volume detach hangs. HP 3par client fails to delete host when node host in 3par host sets

[Yehia Beyh]

When an HP 3par host in host set, the cinder volume detach will hang. Looking at the log files, the exception shows the following exception after deleting all the vluns, the host entry is a pre-existing one since the host storage is using the same 3par system:

cinder.openstack.common.rpc.amqp HTTPConflict: Conflict (HTTP 409) 77 - host is a member of a set

in master/cinder/volume/drivers/san/hp/hp_3par_common.py

def delete_vlun(self, volume, hostname):
        volume_name = self._get_3par_vol_name(volume['id'])
        vlun = self._get_vlun(volume_name, hostname)

        if vlun is not None:
            # VLUN Type of MATCHED_SET 4 requires the port to be provided
            if self.VLUN_TYPE_MATCHED_SET == vlun['type']:
                self.client.deleteVLUN(volume_name, vlun['lun'], hostname,
                                       vlun['portPos'])
            else:
                self.client.deleteVLUN(volume_name, vlun['lun'], hostname)

        try:
            self._delete_3par_host(hostname)
            self._remove_hosts_naming_dict_host(hostname)
 >> except hpexceptions.HTTPConflict as ex:
 >> # host will only be removed after all vluns
 >> # have been removed
 >> if 'has exported VLUN' in ex.get_description():
 >> pass
 >> else:
 >> raise

Yes, the problem occurred in Havana. I believe the problem is in Icehouse as well, but I have not tested it yet.

Log info:
ccontrol': 'no-cache',
 'connection': 'close',
 'date': 'Fri, 02 May 2014 17:32:17 GMT',
 'pragma': 'no-cache',
 'server': 'hp3par-wsapi',
 'status': '200'}
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:166
2014-05-02 17:31:23.698 22459 DEBUG hp3parclient.http [-] RESP BODY:
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:167
2014-05-02 17:31:23.699 22459 DEBUG hp3parclient.http [-]
REQ: curl -i https://192.168.3.20:8080/api/v1/hosts/kvm1-4 DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 272d1-c810c89243580a0047fec3b7c713b650-a1d66353" -H "Accept: application/json" -H "User-Agent: python-3parclient"
 _http_log_req /usr/lib/python2.6/site-packages/hp3parclient/http.py:159
2014-05-02 17:31:23.866 22459 DEBUG hp3parclient.http [-] RESP:{'connection': 'close',
 'content-type': 'application/json',
 'date': 'Fri, 02 May 2014 17:32:17 GMT',
 'server': 'hp3par-wsapi',
 'status': '409'}
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:166
2014-05-02 17:31:23.867 22459 DEBUG hp3parclient.http [-] RESP BODY:{"code":77,"desc":"host is a member of a set"}
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:167
2014-05-02 17:31:23.868 22459 DEBUG hp3parclient.http [-]
REQ: curl -i https://192.168.3.20:8080/api/v1/credentials/272d1-c810c89243580a0047fec3b7c713b650-a1d66353 DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 272d1-c810c89243580a0047fec3b7c713b650-a1d66353" -H "Accept: application/json" -H "User-Agent: python-3parclient"
 _http_log_req /usr/lib/python2.6/site-packages/hp3parclient/http.py:159
2014-05-02 17:31:23.887 22459 DEBUG hp3parclient.http [-] RESP:{'cache-control': 'no-cache',
 'connection': 'close',
 'date': 'Fri, 02 May 2014 17:32:17 GMT',
 'pragma': 'no-cache',
 'server': 'hp3par-wsapi',
 'status': '200'}
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:166
2014-05-02 17:31:23.888 22459 DEBUG hp3parclient.http [-] RESP BODY:
 _http_log_resp /usr/lib/python2.6/site-packages/hp3parclient/http.py:167
2014-05-02 17:31:23.889 22459 DEBUG cinder.volume.drivers.san.hp.hp_3par_common [req-2118f4aa-4468-41cd-bfba-2c055d2d3275 e08faaac660b4cefa8371d37e2717113 66c49057ea4d478e975c576a926a1415] Disconnect from 3PAR client_logout /usr/lib/python2.6/site-packages/cinder/volume/drivers/san/hp/hp_3par_common.py:201
2014-05-02 17:31:23.890 22459 DEBUG cinder.openstack.common.lockutils [req-2118f4aa-4468-41cd-bfba-2c055d2d3275 e08faaac660b4cefa8371d37e2717113 66c49057ea4d478e975c576a926a1415] Released file lock "3par" at /var/lib/cinder/tmp/cinder-3par for method "terminate_connection"... inner /usr/lib/python2.6/site-packages/cinder/openstack/common/lockutils.py:239
2014-05-02 17:31:23.891 22459 ERROR cinder.openstack.common.rpc.amqp [req-2118f4aa-4468-41cd-bfba-2c055d2d3275 e08faaac660b4cefa8371d37e2717113 66c49057ea4d478e975c576a926a1415] Exception during message handling
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/amqp.py", line 441, in _process_data
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp **args)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/dispatcher.py", line 148, in dispatch
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 819, in wrapper
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp return func(self, *args, **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 658, in terminate_connection
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp self.driver.terminate_connection(volume_ref, connector, force=force)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/openstack/common/lockutils.py", line 233, in inner
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp retval = f(*args, **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/san/hp/hp_3par_fc.py", line 233, in terminate_connection
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp wwn=connector['wwpns'])
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/san/hp/hp_3par_common.py", line 1099, in terminate_connection
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp self.delete_vlun(volume, hostname)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/san/hp/hp_3par_common.py", line 546, in delete_vlun
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp self._delete_3par_host(hostname)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/san/hp/hp_3par_common.py", line 408, in _delete_3par_host
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp self.client.deleteHost(hostname)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/hp3parclient/client.py", line 388, in deleteHost
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp reponse, body = self.http.delete('/hosts/%s' % name)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/hp3parclient/http.py", line 327, in delete
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp return self._cs_request(url, 'DELETE', **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/hp3parclient/http.py", line 231, in _cs_request
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/hp3parclient/http.py", line 205, in _time_request
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp resp, body = self.request(url, method, **kwargs)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/hp3parclient/http.py", line 199, in request
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp raise exceptions.from_response(resp, body)
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp HTTPConflict: Conflict (HTTP 409) 77 - host is a member of a set
2014-05-02 17:31:23.891 22459 TRACE cinder.openstack.common.rpc.amqp
2014-05-02 17:31:23.897 22459 ERROR cinder.openstack.common.rpc.common [req-2118f4aa-4468-41cd-bfba-2c055d2d3275 e08faaac660b4cefa8371d37e2717113 66c49057ea4d478e975c576a926a1415] Returning exception Conflict (HTTP 409) 77 - host is a member of a set to caller

[Sean Severson (sseverson)]

Confirmed in Icehouse.

Set up a host set on the 3Par prior to testing. It is possible to create and delete empty volumes. It is also possible to attach a volume to an instance. The failure occurs upon attempting to detach the volume, when cinder tries to clear the host from the 3Par.

2014-05-07 14:11:29.065 ERROR cinder.volume.manager [req-18d6d2cb-84bd-4781-b687-ba9f86d59a8d 4ad0ae2b173c4726b3307b5a4e8c0b74 87105c9b3b7948f39f873ba44d89826b] Unable to terminate volume connection: Conflict (HTTP 409) 77 - host is a member of a set
2014-05-07 14:11:29.065 ERROR oslo.messaging.rpc.dispatcher [req-18d6d2cb-84bd-4781-b687-ba9f86d59a8d 4ad0ae2b173c4726b3307b5a4e8c0b74 87105c9b3b7948f39f873ba44d89826b] Exception during message handling: Bad or unexpected response from the storage volume backend API: Unable to terminate volume connection: Conflict (HTTP 409) 77 - host is a member of a set
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 839, in terminate_connection
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher raise exception.VolumeBackendAPIException(data=err_msg)
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher VolumeBackendAPIException: Bad or unexpected response from the storage volume backend API: Unable to terminate volume connection: Conflict (HTTP 409) 77 - host is a member of a set
2014-05-07 14:11:29.065 TRACE oslo.messaging.rpc.dispatcher
2014-05-07 14:11:29.066 ERROR oslo.messaging._drivers.common [req-18d6d2cb-84bd-4781-b687-ba9f86d59a8d 4ad0ae2b173c4726b3307b5a4e8c0b74 87105c9b3b7948f39f873ba44d89826b] Returning exception Bad or unexpected response from the storage volume backend API: Unable to terminate volume connection: Conflict (HTTP 409) 77 - host is a member of a set to caller
2014-05-07 14:11:29.066 ERROR oslo.messaging._drivers.common [req-18d6d2cb-84bd-4781-b687-ba9f86d59a8d 4ad0ae2b173c4726b3307b5a4e8c0b74 87105c9b3b7948f39f873ba44d89826b] ['Traceback (most recent call last):\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch...

[Kurt Martin (kurt-f-martin)]

Hi Yehia,
We have duplicated this behavior on trunk and will work on a fix for trunk first, then request a backport to Icehouse, etc... We do not have a clean work around at this time so we would recommend you not using host sets until we can fix the bug.
~Kurt

[Yehia Beyh (yehia-beyh)]

Hi Kurt,

For our release product, we have release noted the "host sets" limitation. Meanwhile, we made a temporary fix in cinder/volume/drivers/san/hp/hp_3par_common.py

         try:
             self._delete_3par_host(hostname)
             self._remove_hosts_naming_dict_host(hostname)
- except hpexceptions.HTTPConflict as ex:
- # host will only be removed after all vluns
- # have been removed
- if 'has exported VLUN' in ex.get_description():
- pass
- else:
- raise
+ except Exception as ex:
+ LOG.info("Host '%s' could not be deleted: %s", hostname, ex.get_description())

We should not be removing the host for various reasons (host already exists, host a member of host set, host is a cluster member with other vluns attached, etc.). The host entry should be deleted if it gets created by the driver, but we currently do do that approach.

Thanks for your looking into this problem.

-Yehia

[Jeremiah Patterson (jeremiah-patterson)]

Hi Kurt and Yehia,

   This points to a bigger issue that failures to delete the host, in general, may cause the bug behavior. My strong opinion is that the detach process should not be failed or interrupted simply because the driver couldn't remove the host, but rather the exception, any exception, should be simply logged as INFO and allow the detach process to proceed.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit ffa12c98971e35056a7867cd61ba5a39630cc0a7
Author: Mark Sturdevant <email address hidden>
Date: Tue May 27 14:49:34 2014 -0700

    3PAR volume detach with host in a host set

    When deleting the last VLUN for a host, try to
    delete the host. If the host is in a host set
    this will fail. When that happens, log a nice
    message including the reason, but don't fail
    or hang the delete VLUN. Leave hosts in host
    sets.

    Closes-Bug: #1317134

    Change-Id: Ie3f8f94c05a6a318de866598f9e9c4c5d84926f4

[Ilja Livenson (ilja-livenson)]

The same issue happens also in Icehouse -- would it be possible to backport it?