search

hpe-storage / python-hpedockerplugin

HPE Native Docker Plugin
Apache License 2.0
36 stars 64 forks source link

Deleting the last share does not delete Vfs and fpg post mount and unmount of share #648

Closed leenaj0hn closed 5 years ago

leenaj0hn commented 5 years ago

steps

  1. docker volume create -d hpe --name demo_share -o filePersona Creates the default fpg, vfs and share successfully
  2. docker run -it --rm --mount src=demo_share,dst=/data,volume-driver=hpe --name CONT-01 alpine /bin/sh

On the container created a file and exit Share was unmounted and container removed

  1. docker volume rm demo_share This deletes only the file share, does not removed the FPG and vfs.

This is consistently reproducible on recent pulls on tab: hpestorage/legacyvolumeplugin:3.2-prerelease

imran-ansari commented 5 years ago

@leenaj0hn - Could you please attach the logs?

imran-ansari commented 5 years ago

@leenaj0hn - another thing is that when you delete the last share, the FPG, VFS, FSTORE delete happens asynchronously on a child thread. I hope you have not missed that.

leenaj0hn commented 5 years ago

2019-06-14 07:17:11,167 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:17:11,168 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:11,170 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Key not found ETCD: [key=/shares/TestDelete] 2019-06-14 07:17:11,170 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:17:11,170 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:17:11,172 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Get volbyname: volname is TestDelete 2019-06-14 07:17:11,172 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread vol obj read from etcd : None 2019-06-14 07:17:11,172 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT_BLOCK on volume TestDelete 2019-06-14 07:17:11,173 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_volume_snap_details 2019-06-14 07:17:11,173 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args (None, 'TestDelete') 2019-06-14 07:17:11,173 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:17:11,174 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:17:11,175 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Get volbyname: volname is TestDelete 2019-06-14 07:17:11,175 [INFO] hpedockerplugin.volume_manager [140636372319112] MainThread Value of volinfo is: None 2019-06-14 07:17:11,175 [WARNING] hpedockerplugin.volume_manager [140636372319112] MainThread ('Volume Get: Volume name not found %s', 'TestDelete') 2019-06-14 07:17:11,177 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:17:11,179 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Get volbyname: volname is TestDelete 2019-06-14 07:17:11,179 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:11,180 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Key not found ETCD: [key=/shares/TestDelete] 2019-06-14 07:17:11,180 [INFO] hpedockerplugin.request_router [140636372319112] MainThread route_create_request: Entering... 2019-06-14 07:17:11,181 [INFO] hpedockerplugin.request_context [140636372319112] MainThread build_request_context: Entering... 2019-06-14 07:17:11,181 [INFO] hpedockerplugin.request_context [140636372319112] MainThread _create_share_req_ctxt: Entering... 2019-06-14 07:17:11,181 [INFO] hpedockerplugin.request_context [140636372319112] MainThread Validating options for operation 'create share' 2019-06-14 07:17:11,181 [INFO] hpedockerplugin.request_context [140636372319112] MainThread _create_share_req_params: Entering... 2019-06-14 07:17:11,182 [INFO] hpedockerplugin.request_context [140636372319112] MainThread _create_share_req_params: {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None} 2019-06-14 07:17:11,182 [INFO] hpedockerplugin.request_context [140636372319112] MainThread _create_share_req_ctxt: Exiting: {'orchestrator': 'file', 'operation': 'create_share', 'kwargs': {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None}} 2019-06-14 07:17:11,182 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:17:11,183 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request create_share 2019-06-14 07:17:11,183 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args () 2019-06-14 07:17:11,183 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None} 2019-06-14 07:17:11,184 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Try locking name TestDelete 2019-06-14 07:17:11,185 [INFO] hpedockerplugin.request_router [140636372319112] MainThread route_create_request: Return value: {"Err": ""} 2019-06-14 07:17:11,185 [DEBUG] etcd.client [140636216802024] Thread-15 Writing TestDelete to key /share-lock/TestDelete ttl=None dir=False append=False 2019-06-14 07:17:11,188 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:17:11,189 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Name is locked : TestDelete 2019-06-14 07:17:11,189 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:11,190 [INFO] hpedockerplugin.synchronization [140636216802024] Thread-15 Lock acquired: [caller=_create_share, lock-name=TestDelete] 2019-06-14 07:17:11,191 [DEBUG] etcd.client [140636216802024] Thread-15 Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:11,192 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Key not found ETCD: [key=/shares/TestDelete] 2019-06-14 07:17:11,193 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:17:11,194 [INFO] hpedockerplugin.etcdutil [140636216802024] Thread-15 Key not found ETCD: [key=/shares/TestDelete] 2019-06-14 07:17:11,195 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:17:11,195 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Creating share TestDelete... 2019-06-14 07:17:11,197 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Try locking name DEFAULT/SHASHI-CPG 2019-06-14 07:17:11,198 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Get volbyname: volname is TestDelete 2019-06-14 07:17:11,198 [DEBUG] etcd.client [140636216802024] Thread-15 Writing DEFAULT/SHASHI-CPG to key /fp-cpg-lock/DEFAULT/SHASHI-CPG ttl=None dir=False append=False 2019-06-14 07:17:11,199 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread vol obj read from etcd : None 2019-06-14 07:17:11,200 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT_BLOCK on volume TestDelete 2019-06-14 07:17:11,200 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_path 2019-06-14 07:17:11,201 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Name is locked : DEFAULT/SHASHI-CPG 2019-06-14 07:17:11,201 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args () 2019-06-14 07:17:11,202 [INFO] hpedockerplugin.cmd.cmd_initshare [140636216802024] Thread-15 Initializing status for share TestDelete... 2019-06-14 07:17:11,202 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:17:11,203 [DEBUG] etcd.client [140636216802024] Thread-15 Writing {"id": null, "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": null, "vfs": null, "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "CREATING"} to key /shares/TestDelete ttl=None dir=False append=False 2019-06-14 07:17:11,203 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:17:11,205 [INFO] hpedockerplugin.etcdutil [140636216802024] Thread-15 Write key: /shares/TestDelete to ETCD, value is: {"id": null, "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": null, "vfs": null, "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "CREATING"} 2019-06-14 07:17:11,207 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Get volbyname: volname is TestDelete 2019-06-14 07:17:11,207 [INFO] hpedockerplugin.cmd.cmd_initshare [140636216802024] Thread-15 Status initialized for share TestDelete 2019-06-14 07:17:11,207 [WARNING] hpedockerplugin.volume_manager [140636372319112] MainThread ('Volume Path: Volume name not found %s', 'TestDelete') 2019-06-14 07:17:11,208 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Getting default available FPG... 2019-06-14 07:17:11,210 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Fetching metadata for backend DEFAULT... 2019-06-14 07:17:11,210 [DEBUG] etcd.client [140636216802024] Thread-15 Issuing read for key /file-persona/DEFAULT.metadata with args {} 2019-06-14 07:17:11,212 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Backend metadata: {'ips_in_use': ['192.168.70.14', '192.168.70.14', '192.168.70.14'], 'ips_locked_for_use': [], 'counter': 2, 'default_fpgs': {'SHASHI-CPG': ['DockerFpg_0', 'DockerFpg_1', 'DockerFpg_2']}} 2019-06-14 07:17:11,212 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Checking if default FPG present for CPG SHASHI-CPG... 2019-06-14 07:17:11,212 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Default FPG DockerFpg_0 found for CPG SHASHI-CPG 2019-06-14 07:17:11,212 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Getting FPG DockerFpg_0 from backend... 2019-06-14 07:17:11,213 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:11,213 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:17:11,616 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:18 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-00301576c33a2d1ed76ce14f76743e56-8e50035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:11,618 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"key":"0-00301576c33a2d1ed76ce14f76743e56-8e50035d"}

2019-06-14 07:17:11,619 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/fpgs?query="name EQ DockerFpg_0" -X GET -H "X-Hp3Par-Wsapi-Sessionkey: 0-00301576c33a2d1ed76ce14f76743e56-8e50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:21,897 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:28 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/fpgs?query=%22name%20EQ%20DockerFpg_0%22'}

2019-06-14 07:17:21,900 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"total":1,"members":[{"name":"DockerFpg_0","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423","generation":1,"activePath":"/DockerFpg_0","version":"12.3","creationTimeSec":1560439032,"creationTime8601":"2019-06-13T20:47:12+05:30","fileSystemNumber":62,"availCapacityGiB":16375.53,"freeCapacityGiB":16375.53,"usedCapacityGiB":8.47,"totalCapacityGiB":16384.00,"freeFiles":35473709712,"usedFiles":100,"cpg":"swap_fs_cpg","segments":[{"segmentNumber":1,"FSCKState":1,"FSCKPhaseRequired":1}],"domains":[{"uuid":"c818ba13-0a51-4f82-956f-44582f5f25e6","owner":1,"filesetName":"fileset1","ipfsType":1,"nodes":[],"volumeIds":[14171]}],"volumes":[{"volumeName":"DockerFpg_0.1","volumeId":14171,"nodes":[1,0],"capacityGiB":16384.00}],"activeState":1,"primaryNode":1,"alternateNode":0,"currentNode":1,"comment":"Docker created FPG","overAllState":1,"freezeState":2,"isolationState":1,"healthDescription":"FPG is activated and operational","links":[{"href":"https://192.168.67.6:8080/api/v1/fpgs/14b1451a-996a-4d95-b2f0-0bf6840ec423","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/cpgs/swap_fs_cpg","rel":"cpg"},{"href":"https://192.168.67.6:8080/api/v1/volumesets/DockerFpg_0","rel":"volumeSet"},{"volumeLinks":[{"href":"https://192.168.67.6:8080/api/v1/volumes/DockerFpg_0.1","rel":"volume"}]}]}]}

2019-06-14 07:17:21,901 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-00301576c33a2d1ed76ce14f76743e56-8e50035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-00301576c33a2d1ed76ce14f76743e56-8e50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:21,937 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:28 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-00301576c33a2d1ed76ce14f76743e56-8e50035d'}

2019-06-14 07:17:21,938 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:

2019-06-14 07:17:21,939 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 {'name': 'DockerFpg_0', 'id': '14b1451a-996a-4d95-b2f0-0bf6840ec423', 'uuid': '14b1451a-996a-4d95-b2f0-0bf6840ec423', 'generation': 1, 'activePath': '/DockerFpg_0', 'version': '12.3', 'creationTimeSec': 1560439032, 'creationTime8601': '2019-06-13T20:47:12+05:30', 'fileSystemNumber': 62, 'availCapacityGiB': 16375.53, 'freeCapacityGiB': 16375.53, 'usedCapacityGiB': 8.47, 'totalCapacityGiB': 16384.0, 'freeFiles': 35473709712, 'usedFiles': 100, 'cpg': 'swap_fs_cpg', 'segments': [{'segmentNumber': 1, 'FSCKState': 1, 'FSCKPhaseRequired': 1}], 'domains': [{'uuid': 'c818ba13-0a51-4f82-956f-44582f5f25e6', 'owner': 1, 'filesetName': 'fileset1', 'ipfsType': 1, 'nodes': [], 'volumeIds': [14171]}], 'volumes': [{'volumeName': 'DockerFpg_0.1', 'volumeId': 14171, 'nodes': [1, 0], 'capacityGiB': 16384.0}], 'activeState': 1, 'primaryNode': 1, 'alternateNode': 0, 'currentNode': 1, 'comment': 'Docker created FPG', 'overAllState': 1, 'freezeState': 2, 'isolationState': 1, 'healthDescription': 'FPG is activated and operational', 'links': [{'href': 'https://192.168.67.6:8080/api/v1/fpgs/14b1451a-996a-4d95-b2f0-0bf6840ec423', 'rel': 'self'}, {'href': 'https://192.168.67.6:8080/api/v1/virtualfileservers?query="fpg EQ DockerFpg_0"', 'rel': 'virtualfileserver'}, {'href': 'https://192.168.67.6:8080/api/v1/cpgs/swap_fs_cpg', 'rel': 'cpg'}, {'href': 'https://192.168.67.6:8080/api/v1/volumesets/DockerFpg_0', 'rel': 'volumeSet'}, {'volumeLinks': [{'href': 'https://192.168.67.6:8080/api/v1/volumes/DockerFpg_0.1', 'rel': 'volume'}]}]} 2019-06-14 07:17:21,939 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Getting all quotas for FPG DockerFpg_0... 2019-06-14 07:17:21,939 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:21,940 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:17:22,019 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:28 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-98f762d4c23a0636fe8949c109986954-9850035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:22,020 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"key":"0-98f762d4c23a0636fe8949c109986954-9850035d"}

2019-06-14 07:17:22,021 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/filepersonaquotas?query="fpg EQ DockerFpg_0" -X GET -H "X-Hp3Par-Wsapi-Sessionkey: 0-98f762d4c23a0636fe8949c109986954-9850035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:25,440 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:17:25,441 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:25,444 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'CREATING'} 2019-06-14 07:17:25,444 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:17:25,445 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:17:25,445 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:25,447 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'CREATING'} 2019-06-14 07:17:25,448 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Populating cache TestDelete, DEFAULT 2019-06-14 07:17:25,448 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:17:25,449 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_share_details 2019-06-14 07:17:25,449 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'CREATING'},) 2019-06-14 07:17:25,450 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:17:25,450 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing implementation details from share TestDelete... 2019-06-14 07:17:25,451 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Implementation details removed: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'CREATING'} 2019-06-14 07:17:25,451 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Returning share: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': '1024 GiB', 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'CREATING', 'sharePath': None} 2019-06-14 07:17:25,452 [DEBUG] hpedockerplugin.file_manager [140636372319112] MainThread Get share: {"Err": "", "Volume": {"Name": "TestDelete", "Mountpoint": "", "Devicename": "", "Status": {"backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": null, "vfs": null, "name": "TestDelete", "size": "1024 GiB", "protocol": "nfs", "clientIPs": [], "fsMode": null, "fsOwner": null, "status": "CREATING", "sharePath": null}}} 2019-06-14 07:17:25,454 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:17:25,454 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:17:25,456 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': None, 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': None, 'vfs': None, 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'CREATING'} 2019-06-14 07:17:27,002 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:33 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/filepersonaquotas?query=%22fpg%20EQ%20DockerFpg_0%22'}

2019-06-14 07:17:27,004 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"total":4,"members":[{"name":"scfiledemo1-206323f8-8e25-11e9-a76a-f40343b8bc70","id":"14804171356879541642","key":3,"fpg":"DockerFpg_0","vfs":"DockerVfs_0","currentFileLimit":8,"softFileLimit":0,"hardFileLimit":0,"graceFileLimitInSec":0,"currentBlockMiB":0,"softBlockMiB":10240,"hardBlockMiB":10240,"graceBlockInSec":0,"overallState":1,"type":3,"links":[{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas/14804171356879541642","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/filestores?query=\"name EQ scfiledemo1-206323f8-8e25-11e9-a76a-f40343b8bc70 AND fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0\"","rel":"filestore"}]},{"name":"scfiledemo1-9c7943eb-8e44-11e9-a76a-f40343b8bc70","id":"5430815335030867838","key":4,"fpg":"DockerFpg_0","vfs":"DockerVfs_0","currentFileLimit":2,"softFileLimit":0,"hardFileLimit":0,"graceFileLimitInSec":0,"currentBlockMiB":0,"softBlockMiB":10240,"hardBlockMiB":10240,"graceBlockInSec":0,"overallState":1,"type":3,"links":[{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas/5430815335030867838","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/filestores?query=\"name EQ scfiledemo1-9c7943eb-8e44-11e9-a76a-f40343b8bc70 AND fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0\"","rel":"filestore"}]},{"name":"scfiledemo1-8bb5a206-8e46-11e9-a76a-f40343b8bc70","id":"12685805485491890471","key":5,"fpg":"DockerFpg_0","vfs":"DockerVfs_0","currentFileLimit":5,"softFileLimit":0,"hardFileLimit":0,"graceFileLimitInSec":0,"currentBlockMiB":0,"softBlockMiB":10240,"hardBlockMiB":10240,"graceBlockInSec":0,"overallState":1,"type":3,"links":[{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas/12685805485491890471","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/filestores?query=\"name EQ scfiledemo1-8bb5a206-8e46-11e9-a76a-f40343b8bc70 AND fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0\"","rel":"filestore"}]},{"name":"MySh_01","id":"18245818041339429155","key":6,"fpg":"DockerFpg_0","vfs":"DockerVfs_0","currentFileLimit":2,"softFileLimit":0,"hardFileLimit":0,"graceFileLimitInSec":0,"currentBlockMiB":0,"softBlockMiB":1048576,"hardBlockMiB":1048576,"graceBlockInSec":0,"overallState":1,"type":3,"links":[{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas/18245818041339429155","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/filestores?query=\"name EQ MySh_01 AND fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0\"","rel":"filestore"}]}]}

2019-06-14 07:17:27,005 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-98f762d4c23a0636fe8949c109986954-9850035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-98f762d4c23a0636fe8949c109986954-9850035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:27,036 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:33 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-98f762d4c23a0636fe8949c109986954-9850035d'}

2019-06-14 07:17:27,037 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:

2019-06-14 07:17:27,038 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Total capacity of FPG DockerFpg_0: 16375.53 GiB 2019-06-14 07:17:27,038 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Capacity used on FPG DockerFpg_0 is 1054.0 GiB 2019-06-14 07:17:27,038 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Available capacity on FPG DockerFpg_0 is 15321.53 GiB 2019-06-14 07:17:27,038 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 FPG available capacity in GiB: 15321.53 2019-06-14 07:17:27,039 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Found default FPG with enough available capacity 15321.53 GiB to create share of size 1024.0 GiB 2019-06-14 07:17:27,039 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:27,040 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:17:27,860 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:34 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-c3808a78617e0e2e1ddb8d610347846b-9e50035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:27,861 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"key":"0-c3808a78617e0e2e1ddb8d610347846b-9e50035d"}

2019-06-14 07:17:27,863 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/virtualfileservers?query="fpg EQ DockerFpg_0" -X GET -H "X-Hp3Par-Wsapi-Sessionkey: 0-c3808a78617e0e2e1ddb8d610347846b-9e50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:36,750 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:43 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/virtualfileservers?query=%22fpg%20EQ%20DockerFpg_0%22'}

2019-06-14 07:17:36,752 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"total":1,"members":[{"name":"DockerVfs_0","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-2","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-2","fpg":"DockerFpg_0","overallState":1,"blockGraceTimeSec":604800,"inodeGraceTimeSec":604800,"comment":"Docker created VFS","snapshotQuotaEnabled":false,"IPInfo":[{"policyId":"c87ddb540cbb4114a9e99c3b1263bbde","fpg":"DockerFpg_0","vfs":"DockerVfs_0","IPAddr":"192.168.110.5","netmask":"255.255.192.0","networkName":"user","vlanTag":0}],"certificateInfo":[{"name":"defaultCertificate","validFrom8601":"2019-06-13T20:48:47+05:30","validFromSec":1560439127,"validUntil8601":"2022-06-12T20:48:47+05:30","validUntilSec":1655047127,"issuer":"CN=3PAR, O=Hewlett Packard Enterprise Development LP, L=Palo Alto, ST=CA, C=US","subIssuer":"CN=3PAR, O=Hewlett Packard Enterprise Development LP, L=Palo Alto, ST=CA, C=US","serialNumber":"0","version":3,"contents":"-----BEGIN CERTIFICATE-----\nMIIDoTCCAomgAwIBAgIBADANBgkqhkiG9w0BAQsFADBxMQswCQYDVQQGEwJVUzEL\nMAkGA1UECAwCQ0ExEjAQBgNVBAcMCVBhbG8gQWx0bzEyMDAGA1UECgwpSGV3bGV0\ndCBQYWNrYXJkIEVudGVycHJpc2UgRGV2ZWxvcG1lbnQgTFAxDTALBgNVBAMMBDNQ\nQVIwHhcNMTkwNjEzMTUxODQ3WhcNMjIwNjEyMTUxODQ3WjBxMQswCQYDVQQGEwJV\nUzELMAkGA1UECAwCQ0ExEjAQBgNVBAcMCVBhbG8gQWx0bzEyMDAGA1UECgwpSGV3\nbGV0dCBQYWNrYXJkIEVudGVycHJpc2UgRGV2ZWxvcG1lbnQgTFAxDTALBgNVBAMM\nBDNQQVIwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCzF9wa27OPauEd\nWLyQ+AnEf+TF3tw+jCicvyWDRgPL6UIsIBi2ZCCwT9u14caoQv5b61f8wLH0HhMF\n9s0wVZDCBfra7gjhuN1paQjS5XGgpzvCoNmHoou9O9wiM6z+8aubeNIBOlFFozdt\naG2HwjjjtNqUks9ePq/guKHV5U/gfqxSZ1AeEpNjcYBV/SADqHaFbx7OUH3AqVkA\nA4zym7OWG8Y0dGXMqtS4cNKlLUxtuLEQam+4+7JMNXY7xe8+SqKPGaQV3pvVAe5D\n1ZJmKwdGnF9hyULK16mV8Qb2lrR0rXnce7rlH3rFN+qW+Fyy/Tz+pzdP7zkV8teG\ndsRM9hEHAgMBAAGjRDBCMAwGA1UdEwQFMAMBAf8wEwYDVR0lBAwwCgYIKwYBBQUH\nAwEwHQYDVR0OBBYEFFA9DWrrpUbEU6PFZKeYw5HPCBcGMA0GCSqGSIb3DQEBCwUA\nA4IBAQAVvEUMQLXDuXysH6yU87VkW/TtMHV3vHYLleBfW16btL6UjtK0NqdblvWt\nP9VN7f7RvE1KhGp0UTckvzjcIeCVMjbnMtOkH3oUDgqcWKlHnCe0R5v78oE2hXX0\nmxAOAdzKtyGWpLTRIIzPrhqLZonEmJxP7UdONTexbUZ7/yXD4FLOXsq6/H2i8HE4\nNUoSQ6q5qdgrev5zCcSTeUWIFdl1u6KgGcjNcHoXalTsTQrWgjqTEAgIlXWNxc+u\nZEkFQ+JyT02+VgpcYgw8Ub70o4Gztvg4Bk33tJX5hN/tCLw1u04wZBNw170QR2sY\nL288I6EscStNt2S4QEObg7RdTVEH\n-----END CERTIFICATE-----"}],"links":[{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers/14b1451a-996a-4d95-b2f0-0bf6840ec423-2","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/filestores?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0\"","rel":"filestore"},{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas?query=\"vfs EQ DockerVfs_0\"","rel":"filepersonaquota"}]}]}

2019-06-14 07:17:36,753 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-c3808a78617e0e2e1ddb8d610347846b-9e50035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-c3808a78617e0e2e1ddb8d610347846b-9e50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:36,789 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:43 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-c3808a78617e0e2e1ddb8d610347846b-9e50035d'}

2019-06-14 07:17:36,790 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:

2019-06-14 07:17:36,790 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Creating share TestDelete... 2019-06-14 07:17:36,791 [INFO] hpedockerplugin.cmd.cmd_createshare [140636216802024] Thread-15 Creating share TestDelete on the backend 2019-06-14 07:17:36,791 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:36,791 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:17:36,833 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:45:43 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-c182c5a3e599b89acc5feef7e1e72e09-a750035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:36,834 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"key":"0-c182c5a3e599b89acc5feef7e1e72e09-a750035d"}

2019-06-14 07:17:36,835 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/fileshares/ -X POST -H "X-Hp3Par-Wsapi-Sessionkey: 0-c182c5a3e599b89acc5feef7e1e72e09-a750035d" -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:36,835 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"name": "TestDelete", "type": 1, "vfs": "DockerVfs_0", "fpg": "DockerFpg_0", "shareDirectory": null, "fstore": null, "nfsOptions": "rw,no_root_squash,secure", "nfsClientlist": ["127.0.0.1"], "comment": "Docker created share"}

2019-06-14 07:17:58,398 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:46:05 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/fileshares/8735110495813731959' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:58,400 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"links":[{"href":"https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959","rel":"self"}]}

2019-06-14 07:17:58,401 [DEBUG] hpedockerplugin.hpe.hpe_3par_mediator [140636216802024] Thread-15 Share created successfully: {'links': [{'href': 'https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959', 'rel': 'self'}]} 2019-06-14 07:17:58,401 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-c182c5a3e599b89acc5feef7e1e72e09-a750035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-c182c5a3e599b89acc5feef7e1e72e09-a750035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:17:58,436 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:46:05 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-c182c5a3e599b89acc5feef7e1e72e09-a750035d'}

2019-06-14 07:17:58,437 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:

2019-06-14 07:17:58,437 [DEBUG] etcd.client [140636216802024] Thread-15 Writing {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]]} to key /shares/TestDelete ttl=None dir=False append=False 2019-06-14 07:17:58,439 [INFO] hpedockerplugin.etcdutil [140636216802024] Thread-15 Write key: /shares/TestDelete to ETCD, value is: {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]]} 2019-06-14 07:17:58,440 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Share created successfully TestDelete 2019-06-14 07:17:58,440 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Setting quota for share TestDelete... 2019-06-14 07:17:58,440 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:58,441 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:17:58,481 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:46:05 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-ce16d23302dd474725f078a33bfc6ca1-bd50035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:17:58,483 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"key":"0-ce16d23302dd474725f078a33bfc6ca1-bd50035d"}

2019-06-14 07:17:58,484 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/filepersonaquotas/ -X POST -H "X-Hp3Par-Wsapi-Sessionkey: 0-ce16d23302dd474725f078a33bfc6ca1-bd50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:17:58,485 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ BODY: {"name": "TestDelete", "type": 3, "vfs": "DockerVfs_0", "fpg": "DockerFpg_0", "softBlockMiB": 1048576, "hardBlockMiB": 1048576}

2019-06-14 07:18:49,302 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:46:56 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/filepersonaquotas/2605186662134880501' 'Connection': 'close' 'status': '201'}

2019-06-14 07:18:49,304 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:{"links":[{"href":"https://192.168.67.6:8080/api/v1/filepersonaquotas/2605186662134880501","rel":"self"}]}

2019-06-14 07:18:49,305 [DEBUG] hpedockerplugin.hpe.hpe_3par_mediator [140636216802024] Thread-15 Quota successfully set: resp={'Date': 'Fri, 14 Jun 2019 07:46:56 GMT', 'Server': 'hp3par-wsapi', 'Cache-Control': 'no-cache', 'Pragma': 'no-cache', 'Content-Type': 'application/json', 'Location': '/api/v1/filepersonaquotas/2605186662134880501', 'Connection': 'close', 'status': '201'}, body={'links': [{'href': 'https://192.168.67.6:8080/api/v1/filepersonaquotas/2605186662134880501', 'rel': 'self'}]} 2019-06-14 07:18:49,305 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-ce16d23302dd474725f078a33bfc6ca1-bd50035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-ce16d23302dd474725f078a33bfc6ca1-bd50035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:18:49,342 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP:{'Date': 'Fri, 14 Jun 2019 07:46:56 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-ce16d23302dd474725f078a33bfc6ca1-bd50035d'}

2019-06-14 07:18:49,343 [DEBUG] hpe3parclient.http [140636216802024] Thread-15 RESP BODY:

2019-06-14 07:18:49,344 [DEBUG] etcd.client [140636216802024] Thread-15 Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:18:49,345 [DEBUG] etcd.client [140636216802024] Thread-15 Writing {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501"} to key /shares/TestDelete ttl=None dir=False append=False 2019-06-14 07:18:49,347 [INFO] hpedockerplugin.etcdutil [140636216802024] Thread-15 Write key: /shares/TestDelete to ETCD, value is: {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501"} 2019-06-14 07:18:49,347 [INFO] hpedockerplugin.cmd.cmd_setquota [140636216802024] Thread-15 Updated quota metadata for share: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:18:49,348 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Quota set for share successfully TestDelete 2019-06-14 07:18:49,348 [INFO] hpedockerplugin.file_manager [140636216802024] Thread-15 Share creation done using FPG DockerFpg_0 2019-06-14 07:18:49,348 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Try unlocking name DEFAULT/SHASHI-CPG 2019-06-14 07:18:49,348 [DEBUG] etcd.client [140636216802024] Thread-15 Deleting /fp-cpg-lock/DEFAULT/SHASHI-CPG recursive=None dir=None extra args={} 2019-06-14 07:18:49,349 [DEBUG] etcd.client [140636216802024] Thread-15 Calculated params = {} 2019-06-14 07:18:49,350 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Name is unlocked : DEFAULT/SHASHI-CPG 2019-06-14 07:18:49,350 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Try unlocking name TestDelete 2019-06-14 07:18:49,351 [DEBUG] etcd.client [140636216802024] Thread-15 Deleting /share-lock/TestDelete recursive=None dir=None extra args={} 2019-06-14 07:18:49,351 [DEBUG] etcd.client [140636216802024] Thread-15 Calculated params = {} 2019-06-14 07:18:49,353 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-15 Name is unlocked : TestDelete 2019-06-14 07:18:49,353 [INFO] hpedockerplugin.synchronization [140636216802024] Thread-15 Lock released: [caller=_create_share, lock-name=TestDelete] 2019-06-14 07:20:42,850 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:20:42,851 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:20:42,854 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:20:42,854 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:20:42,855 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:20:42,855 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:20:42,856 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_share_details 2019-06-14 07:20:42,856 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'},) 2019-06-14 07:20:42,857 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:20:42,857 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing implementation details from share TestDelete... 2019-06-14 07:20:42,858 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Implementation details removed: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']]} 2019-06-14 07:20:42,858 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Returning share: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': '1024 GiB', 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'sharePath': '192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete'} 2019-06-14 07:20:42,859 [DEBUG] hpedockerplugin.file_manager [140636372319112] MainThread Get share: {"Err": "", "Volume": {"Name": "TestDelete", "Mountpoint": "", "Devicename": "", "Status": {"backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": "1024 GiB", "protocol": "nfs", "clientIPs": [], "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "sharePath": "192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete"}}} 2019-06-14 07:20:42,862 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:20:42,862 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:20:42,865 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:43:25,635 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:43:25,636 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:43:25,638 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:43:25,639 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:43:25,639 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:43:25,640 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:43:25,640 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_share_details 2019-06-14 07:43:25,641 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'},) 2019-06-14 07:43:25,641 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:43:25,642 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing implementation details from share TestDelete... 2019-06-14 07:43:25,642 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Implementation details removed: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']]} 2019-06-14 07:43:25,643 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Returning share: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': '1024 GiB', 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'sharePath': '192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete'} 2019-06-14 07:43:25,643 [DEBUG] hpedockerplugin.file_manager [140636372319112] MainThread Get share: {"Err": "", "Volume": {"Name": "TestDelete", "Mountpoint": "", "Devicename": "", "Status": {"backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": "1024 GiB", "protocol": "nfs", "clientIPs": [], "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "sharePath": "192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete"}}} 2019-06-14 07:43:25,665 [DEBUG] hpe_storage_api [140636372319112] MainThread In volumedriver_mount 2019-06-14 07:43:25,666 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try locking name TestDelete 2019-06-14 07:43:25,667 [DEBUG] etcd.client [140636372319112] MainThread Writing TestDelete to key /volumes-lock/TestDelete ttl=None dir=False append=False 2019-06-14 07:43:25,671 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is locked : TestDelete 2019-06-14 07:43:25,671 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock acquired: [caller=route_mount_request, lock-name=TestDelete] 2019-06-14 07:43:25,672 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:43:25,672 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:43:25,674 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:43:25,674 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:43:25,675 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:43:25,675 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:43:25,676 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request mount_share 2019-06-14 07:43:25,676 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'}, 'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b') 2019-06-14 07:43:25,677 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:43:25,677 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Share TestDelete is in AVAILABLE state. Attempting mount... 2019-06-14 07:43:25,678 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Mount directory for file is /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b 2019-06-14 07:43:25,678 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:43:25,679 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:43:25,727 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:11:32 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-e87d1f8b8db74183ed96c099c6c038d8-b456035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:43:25,728 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:{"key":"0-e87d1f8b8db74183ed96c099c6c038d8-b456035d"}

2019-06-14 07:43:25,729 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959 PUT -H "X-Hp3Par-Wsapi-Sessionkey: 0-e87d1f8b8db74183ed96c099c6c038d8-b456035d" -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:43:25,729 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ BODY: {"nfsClientlistOperation": 1, "nfsClientlist": ["192.168.68.31"]}

2019-06-14 07:43:33,754 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:11:40 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959'}

2019-06-14 07:43:33,756 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:{"links":[{"href":"https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959","rel":"self"}]}

2019-06-14 07:43:33,757 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-e87d1f8b8db74183ed96c099c6c038d8-b456035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-e87d1f8b8db74183ed96c099c6c038d8-b456035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:43:33,807 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:11:40 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-e87d1f8b8db74183ed96c099c6c038d8-b456035d'}

2019-06-14 07:43:33,808 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:

2019-06-14 07:43:33,809 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Creating Directory /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b... 2019-06-14 07:43:33,810 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>: starting process 2019-06-14 07:43:33,823 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: started process 2019-06-14 07:43:33,825 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 56>: process started 2019-06-14 07:43:33,825 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: acquiring wait lock to wait for completion 2019-06-14 07:43:33,825 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: got wait lock 2019-06-14 07:43:33,826 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: exit code not set, waiting on pid 2019-06-14 07:43:33,833 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 56 <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba3ea58> ready to be read from 2019-06-14 07:43:33,835 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 56 <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got errno 5, done reading 2019-06-14 07:43:33,835 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 56 <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba3efd0> ready to be read from 2019-06-14 07:43:33,836 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 56 got no chunk, done reading 2019-06-14 07:43:33,836 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 acquiring buffering lock for flushing buffer 2019-06-14 07:43:33,837 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 got buffering lock for flushing buffer 2019-06-14 07:43:33,837 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 released buffering lock for flushing buffer 2019-06-14 07:43:33,838 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 56 <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 56 [b'/bin/mkdir', b'-p', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got chunk size 0 to flush: b'' 2019-06-14 07:43:33,838 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 acquiring buffering lock for flushing buffer 2019-06-14 07:43:33,839 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 got buffering lock for flushing buffer 2019-06-14 07:43:33,839 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 56 released buffering lock for flushing buffer 2019-06-14 07:43:33,839 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 56 got chunk size 0 to flush: b'' 2019-06-14 07:43:33,840 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mkdir -p /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 56>: process completed 2019-06-14 07:43:33,841 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Directory: /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b successfully created! 2019-06-14 07:43:33,841 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Mounting share path 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete to /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b 2019-06-14 07:43:33,843 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>: starting process 2019-06-14 07:43:33,855 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: started process 2019-06-14 07:43:33,859 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 60>: process started 2019-06-14 07:43:33,859 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: acquiring wait lock to wait for completion 2019-06-14 07:43:33,860 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: got wait lock 2019-06-14 07:43:33,860 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: exit code not set, waiting on pid 2019-06-14 07:43:33,966 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 60 <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ab4d6d8> ready to be read from 2019-06-14 07:43:33,967 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 60 <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got errno 5, done reading 2019-06-14 07:43:33,967 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 60 <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba49828> ready to be read from 2019-06-14 07:43:33,968 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 60 got no chunk, done reading 2019-06-14 07:43:33,968 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 acquiring buffering lock for flushing buffer 2019-06-14 07:43:33,969 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 got buffering lock for flushing buffer 2019-06-14 07:43:33,969 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 released buffering lock for flushing buffer 2019-06-14 07:43:33,969 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 60 <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 60 [b'/bin/mount', b'-t', b'nfs', b'192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got chunk size 0 to flush: b'' 2019-06-14 07:43:33,970 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 acquiring buffering lock for flushing buffer 2019-06-14 07:43:33,970 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 got buffering lock for flushing buffer 2019-06-14 07:43:33,971 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 60 released buffering lock for flushing buffer 2019-06-14 07:43:33,971 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 60 got chunk size 0 to flush: b'' 2019-06-14 07:43:33,972 [INFO] sh.command [140636372319112] MainThread <Command '/bin/mount -t nfs 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 60>: process completed 2019-06-14 07:43:33,973 [DEBUG] hpedockerplugin.file_manager [140636372319112] MainThread Device: 192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete successfully mounted on /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b 2019-06-14 07:43:33,973 [DEBUG] etcd.client [140636372319112] MainThread Writing {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": ["192.168.68.31"], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501", "path_info": {"d7bb9abc-b40e-4c0b-b7a6-a5443b148000": {"e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b": "/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b"}}} to key /shares/TestDelete ttl=None dir=False append=False 2019-06-14 07:43:33,977 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Write key: /shares/TestDelete to ETCD, value is: {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": ["192.168.68.31"], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501", "path_info": {"d7bb9abc-b40e-4c0b-b7a6-a5443b148000": {"e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b": "/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b"}}} 2019-06-14 07:43:33,978 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try unlocking name TestDelete 2019-06-14 07:43:33,978 [DEBUG] etcd.client [140636372319112] MainThread Deleting /volumes-lock/TestDelete recursive=None dir=None extra args={} 2019-06-14 07:43:33,979 [DEBUG] etcd.client [140636372319112] MainThread Calculated params = {} 2019-06-14 07:43:33,981 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is unlocked : TestDelete 2019-06-14 07:43:33,982 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock released: [caller=route_mount_request, lock-name=TestDelete] 2019-06-14 07:49:54,198 [INFO] hpe_storage_api [140636372319112] MainThread In volumedriver_unmount 2019-06-14 07:49:54,199 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try locking name TestDelete 2019-06-14 07:49:54,199 [DEBUG] etcd.client [140636372319112] MainThread Writing TestDelete to key /volumes-lock/TestDelete ttl=None dir=False append=False 2019-06-14 07:49:54,203 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is locked : TestDelete 2019-06-14 07:49:54,204 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock acquired: [caller=route_unmount_request, lock-name=TestDelete] 2019-06-14 07:49:54,205 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:49:54,205 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:49:54,208 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': ['192.168.68.31'], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501', 'path_info': {'d7bb9abc-b40e-4c0b-b7a6-a5443b148000': {'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b': '/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'}}} 2019-06-14 07:49:54,208 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:49:54,209 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:49:54,209 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:49:54,210 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request unmount_share 2019-06-14 07:49:54,210 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': ['192.168.68.31'], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501', 'path_info': {'d7bb9abc-b40e-4c0b-b7a6-a5443b148000': {'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b': '/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'}}}, 'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b') 2019-06-14 07:49:54,210 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:49:54,211 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Unmounting share: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': ['192.168.68.31'], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501', 'path_info': {'d7bb9abc-b40e-4c0b-b7a6-a5443b148000': {'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b': '/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'}}} 2019-06-14 07:49:54,211 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Unmounting share: /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b... 2019-06-14 07:49:54,213 [INFO] sh.command [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>: starting process 2019-06-14 07:49:54,227 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: started process 2019-06-14 07:49:54,229 [INFO] sh.command [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 68>: process started 2019-06-14 07:49:54,230 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: acquiring wait lock to wait for completion 2019-06-14 07:49:54,230 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: got wait lock 2019-06-14 07:49:54,230 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: exit code not set, waiting on pid 2019-06-14 07:49:54,305 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 68 <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba49b00> ready to be read from 2019-06-14 07:49:54,306 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 68 <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got errno 5, done reading 2019-06-14 07:49:54,307 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 68 <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba361d0> ready to be read from 2019-06-14 07:49:54,307 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 68 got no chunk, done reading 2019-06-14 07:49:54,307 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 acquiring buffering lock for flushing buffer 2019-06-14 07:49:54,308 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 got buffering lock for flushing buffer 2019-06-14 07:49:54,308 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 released buffering lock for flushing buffer 2019-06-14 07:49:54,309 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 68 <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 68 [b'/bin/umount', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got chunk size 0 to flush: b'' 2019-06-14 07:49:54,309 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 acquiring buffering lock for flushing buffer 2019-06-14 07:49:54,310 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 got buffering lock for flushing buffer 2019-06-14 07:49:54,310 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 68 released buffering lock for flushing buffer 2019-06-14 07:49:54,311 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 68 got chunk size 0 to flush: b'' 2019-06-14 07:49:54,311 [INFO] sh.command [140636372319112] MainThread <Command '/bin/umount /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 68>: process completed 2019-06-14 07:49:54,312 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing dir: /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b... 2019-06-14 07:49:54,313 [INFO] sh.command [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>: starting process 2019-06-14 07:49:54,327 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: started process 2019-06-14 07:49:54,331 [INFO] sh.command [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 73>: process started 2019-06-14 07:49:54,332 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: acquiring wait lock to wait for completion 2019-06-14 07:49:54,332 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: got wait lock 2019-06-14 07:49:54,333 [DEBUG] sh.command.process [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: exit code not set, waiting on pid 2019-06-14 07:49:54,338 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 73 <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba49d68> ready to be read from 2019-06-14 07:49:54,339 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 73 <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got errno 5, done reading 2019-06-14 07:49:54,340 [DEBUG] sh.command.process [140636216802024] STDOUT/ERR thread for pid 73 <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>: <sh.StreamReader object at 0x7fe86ba49518> ready to be read from 2019-06-14 07:49:54,341 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 73 got no chunk, done reading 2019-06-14 07:49:54,341 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 acquiring buffering lock for flushing buffer 2019-06-14 07:49:54,342 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 got buffering lock for flushing buffer 2019-06-14 07:49:54,342 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 released buffering lock for flushing buffer 2019-06-14 07:49:54,343 [DEBUG] sh.command.process.streamreader [140636216802024] STDOUT/ERR thread for pid 73 <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b'>.<Process 73 [b'/bin/rm', b'-rf', b'/opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b']>.stdout: got chunk size 0 to flush: b'' 2019-06-14 07:49:54,344 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 acquiring buffering lock for flushing buffer 2019-06-14 07:49:54,344 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 got buffering lock for flushing buffer 2019-06-14 07:49:54,345 [DEBUG] sh.stream_bufferer [140636216802024] STDOUT/ERR thread for pid 73 released buffering lock for flushing buffer 2019-06-14 07:49:54,345 [DEBUG] sh.streamreader [140636216802024] STDOUT/ERR thread for pid 73 got chunk size 0 to flush: b'' 2019-06-14 07:49:54,346 [INFO] sh.command [140636372319112] MainThread <Command '/bin/rm -rf /opt/hpe/data/hpedocker-e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b', pid 73>: process completed 2019-06-14 07:49:54,346 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing mount-id 'e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b' from meta-data 2019-06-14 07:49:54,347 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Remove 192.168.68.31 from client IP list 2019-06-14 07:49:54,348 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:49:54,350 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:49:54,393 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:18:01 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-e6c0db8e87cbd7307b68be8714444e1c-3958035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:49:54,394 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:{"key":"0-e6c0db8e87cbd7307b68be8714444e1c-3958035d"}

2019-06-14 07:49:54,395 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959 PUT -H "X-Hp3Par-Wsapi-Sessionkey: 0-e6c0db8e87cbd7307b68be8714444e1c-3958035d" -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:49:54,395 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ BODY: {"nfsClientlistOperation": 2, "nfsClientlist": ["192.168.68.31"]}

2019-06-14 07:50:11,991 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:18:18 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959'}

2019-06-14 07:50:11,993 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:{"links":[{"href":"https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959","rel":"self"}]}

2019-06-14 07:50:11,994 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-e6c0db8e87cbd7307b68be8714444e1c-3958035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-e6c0db8e87cbd7307b68be8714444e1c-3958035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:50:12,026 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:18:18 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-e6c0db8e87cbd7307b68be8714444e1c-3958035d'}

2019-06-14 07:50:12,027 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:

2019-06-14 07:50:12,028 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Share unmounted. Updating ETCD: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:50:12,028 [DEBUG] etcd.client [140636372319112] MainThread Writing {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501"} to key /shares/TestDelete ttl=None dir=False append=False 2019-06-14 07:50:12,031 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Write key: /shares/TestDelete to ETCD, value is: {"id": "8735110495813731959", "backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": 1048576, "readonly": false, "nfsOptions": null, "protocol": "nfs", "clientIPs": [], "comment": null, "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "quota_id": "2605186662134880501"} 2019-06-14 07:50:12,032 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Unmount DONE for share: TestDelete, e2a5ae66044e4a78500b2e590cd04148a33284d7197a202fffb9379a5a745a1b 2019-06-14 07:50:12,032 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try unlocking name TestDelete 2019-06-14 07:50:12,033 [DEBUG] etcd.client [140636372319112] MainThread Deleting /volumes-lock/TestDelete recursive=None dir=None extra args={} 2019-06-14 07:50:12,033 [DEBUG] etcd.client [140636372319112] MainThread Calculated params = {} 2019-06-14 07:50:12,036 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is unlocked : TestDelete 2019-06-14 07:50:12,036 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock released: [caller=route_unmount_request, lock-name=TestDelete] 2019-06-14 07:51:50,139 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares with args {'recursive': True} 2019-06-14 07:51:50,142 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /volumes/ with args {'recursive': True} 2019-06-14 07:52:04,814 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:52:04,814 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:52:04,817 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:52:04,817 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:52:04,818 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:52:04,818 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:52:04,819 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request get_share_details 2019-06-14 07:52:04,819 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'},) 2019-06-14 07:52:04,819 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:52:04,820 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Removing implementation details from share TestDelete... 2019-06-14 07:52:04,821 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Implementation details removed: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']]} 2019-06-14 07:52:04,821 [INFO] hpedockerplugin.file_manager [140636372319112] MainThread Returning share: {'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': '1024 GiB', 'protocol': 'nfs', 'clientIPs': [], 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'sharePath': '192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete'} 2019-06-14 07:52:04,821 [DEBUG] hpedockerplugin.file_manager [140636372319112] MainThread Get share: {"Err": "", "Volume": {"Name": "TestDelete", "Mountpoint": "", "Devicename": "", "Status": {"backend": "DEFAULT", "cpg": "SHASHI-CPG", "fpg": "DockerFpg_0", "vfs": "DockerVfs_0", "name": "TestDelete", "size": "1024 GiB", "protocol": "nfs", "clientIPs": [], "fsMode": null, "fsOwner": null, "status": "AVAILABLE", "vfsIPs": [["192.168.110.5", "255.255.192.0"]], "sharePath": "192.168.110.5:/DockerFpg_0/DockerVfs_0/TestDelete"}}} 2019-06-14 07:52:04,824 [INFO] hpe_storage_api [140636372319112] MainThread Routing remove request... 2019-06-14 07:52:04,825 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try locking name TestDelete 2019-06-14 07:52:04,826 [DEBUG] etcd.client [140636372319112] MainThread Writing TestDelete to key /volumes-lock/TestDelete ttl=None dir=False append=False 2019-06-14 07:52:04,828 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is locked : TestDelete 2019-06-14 07:52:04,829 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock acquired: [caller=route_remove_request, lock-name=TestDelete] 2019-06-14 07:52:04,829 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Fetching share details from ETCD: TestDelete 2019-06-14 07:52:04,829 [DEBUG] etcd.client [140636372319112] MainThread Issuing read for key /shares/TestDelete with args {} 2019-06-14 07:52:04,830 [INFO] hpedockerplugin.file_backend_orchestrator [140636372319112] MainThread Returning share details: {'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'} 2019-06-14 07:52:04,831 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Getting details for volume : TestDelete 2019-06-14 07:52:04,831 [DEBUG] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Returning the backend details from cache TestDelete , DEFAULT 2019-06-14 07:52:04,831 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Operating on backend : DEFAULT on volume TestDelete 2019-06-14 07:52:04,831 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread Request remove_share 2019-06-14 07:52:04,832 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with args ({'id': '8735110495813731959', 'backend': 'DEFAULT', 'cpg': 'SHASHI-CPG', 'fpg': 'DockerFpg_0', 'vfs': 'DockerVfs_0', 'name': 'TestDelete', 'size': 1048576, 'readonly': False, 'nfsOptions': None, 'protocol': 'nfs', 'clientIPs': [], 'comment': None, 'fsMode': None, 'fsOwner': None, 'status': 'AVAILABLE', 'vfsIPs': [['192.168.110.5', '255.255.192.0']], 'quota_id': '2605186662134880501'},) 2019-06-14 07:52:04,832 [INFO] hpedockerplugin.backend_orchestrator [140636372319112] MainThread with kwargs is {} 2019-06-14 07:52:04,832 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Deleting share TestDelete... 2019-06-14 07:52:04,832 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Start delete share TestDelete... 2019-06-14 07:52:04,833 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Deleting share TestDelete from backend... 2019-06-14 07:52:04,833 [INFO] hpedockerplugin.hpe.hpe_3par_mediator [140636372319112] MainThread Mediator:delete_share 8735110495813731959: Entering... 2019-06-14 07:52:04,833 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:52:04,834 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:52:04,874 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:20:11 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:52:04,875 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:{"key":"0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d"}

2019-06-14 07:52:04,876 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959 DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:15,052 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:20:21 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/fileshares/8735110495813731959'}

2019-06-14 07:52:15,054 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:

2019-06-14 07:52:15,055 [DEBUG] hpe3parclient.http [140636372319112] MainThread REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:15,087 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP:{'Date': 'Fri, 14 Jun 2019 08:20:22 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-9dcb63acb5bd94cc6d4368e18cf53d13-bb58035d'}

2019-06-14 07:52:15,088 [DEBUG] hpe3parclient.http [140636372319112] MainThread RESP BODY:

2019-06-14 07:52:15,088 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Share TestDelete deleted from backend 2019-06-14 07:52:15,089 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Removing share entry from ETCD: TestDelete... 2019-06-14 07:52:15,089 [DEBUG] etcd.client [140636372319112] MainThread Deleting /shares/TestDelete recursive=None dir=None extra args={} 2019-06-14 07:52:15,089 [DEBUG] etcd.client [140636372319112] MainThread Calculated params = {} 2019-06-14 07:52:15,092 [INFO] hpedockerplugin.etcdutil [140636372319112] MainThread Deleted key: /shares/TestDelete from ETCD 2019-06-14 07:52:15,092 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636372319112] MainThread Removed share entry from ETCD: TestDelete 2019-06-14 07:52:15,093 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636216802024] Thread-20 Deleting file store TestDelete from backend... 2019-06-14 07:52:15,094 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Try unlocking name TestDelete 2019-06-14 07:52:15,094 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:52:15,095 [DEBUG] etcd.client [140636372319112] MainThread Deleting /volumes-lock/TestDelete recursive=None dir=None extra args={} 2019-06-14 07:52:15,096 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:52:15,097 [DEBUG] etcd.client [140636372319112] MainThread Calculated params = {} 2019-06-14 07:52:15,103 [DEBUG] hpedockerplugin.etcdutil [140636372319112] MainThread Name is unlocked : TestDelete 2019-06-14 07:52:15,103 [INFO] hpedockerplugin.synchronization [140636372319112] MainThread Lock released: [caller=route_remove_request, lock-name=TestDelete] 2019-06-14 07:52:15,141 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:20:22 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:52:15,142 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:{"key":"0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d"}

2019-06-14 07:52:15,143 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/filestores?query="name EQ TestDelete AND fpg EQ DockerFpg_0" -X GET -H "X-Hp3Par-Wsapi-Sessionkey: 0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:23,793 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:20:30 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/filestores?query=%22name%20EQ%20TestDelete%20AND%20fpg%20EQ%20DockerFpg_0%22'}

2019-06-14 07:52:23,795 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:{"total":1,"members":[{"name":"TestDelete","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-9","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-9","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-9","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ TestDelete\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ TestDelete\"","rel":"filestoresnapshots"}]}]}

2019-06-14 07:52:23,796 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-9 DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:55,140 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:21:02 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-9'}

2019-06-14 07:52:55,142 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:

2019-06-14 07:52:55,143 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:55,179 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:21:02 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-1ab546acaaa3d85cda56b52ba6c89a3d-c658035d'}

2019-06-14 07:52:55,180 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:

2019-06-14 07:52:55,181 [INFO] hpedockerplugin.cmd.cmd_deleteshare [140636216802024] Thread-20 File store TestDelete deleted from backend 2019-06-14 07:52:55,181 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-20 Try locking name DEFAULT/SHASHI-CPG/DockerFpg_0 2019-06-14 07:52:55,182 [DEBUG] etcd.client [140636216802024] Thread-20 Writing DEFAULT/SHASHI-CPG/DockerFpg_0 to key /fp-fpg-lock/DEFAULT/SHASHI-CPG/DockerFpg_0 ttl=None dir=False append=False 2019-06-14 07:52:55,184 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-20 Name is locked : DEFAULT/SHASHI-CPG/DockerFpg_0 2019-06-14 07:52:55,185 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials -X POST -H "User-Agent: python-3parclient" -H "Accept: application/json" -H "Content-Type: application/json"

2019-06-14 07:52:55,186 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ BODY: {"user": "3paradm", "password": "3pardata"}

2019-06-14 07:52:55,246 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:21:02 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Location': '/api/v1/credentials/0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d' 'Connection': 'close' 'status': '201'}

2019-06-14 07:52:55,248 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:{"key":"0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d"}

2019-06-14 07:52:55,249 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/filestores?query="fpg EQ DockerFpg_0" -X GET -H "X-Hp3Par-Wsapi-Sessionkey: 0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:57,207 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:21:04 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Content-Type': 'application/json' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/filestores?query=%22fpg%20EQ%20DockerFpg_0%22'}

2019-06-14 07:52:57,209 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:{"total":5,"members":[{"name":".admin","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-2","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-2","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-2","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ .admin\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ .admin\"","rel":"filestoresnapshots"}]},{"name":"scfiledemo1-206323f8-8e25-11e9-a76a-f40343b8bc70","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-3","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-3","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-3","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-206323f8-8e25-11e9-a76a-f40343b8bc70\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-206323f8-8e25-11e9-a76a-f40343b8bc70\"","rel":"filestoresnapshots"}]},{"name":"scfiledemo1-9c7943eb-8e44-11e9-a76a-f40343b8bc70","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-4","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-4","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-4","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-9c7943eb-8e44-11e9-a76a-f40343b8bc70\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-9c7943eb-8e44-11e9-a76a-f40343b8bc70\"","rel":"filestoresnapshots"}]},{"name":"scfiledemo1-8bb5a206-8e46-11e9-a76a-f40343b8bc70","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-5","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-5","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-5","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-8bb5a206-8e46-11e9-a76a-f40343b8bc70\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ scfiledemo1-8bb5a206-8e46-11e9-a76a-f40343b8bc70\"","rel":"filestoresnapshots"}]},{"name":"MySh_01","id":"14b1451a-996a-4d95-b2f0-0bf6840ec423-6","uuid":"14b1451a-996a-4d95-b2f0-0bf6840ec423-6","vfs":"DockerVfs_0","fpg":"DockerFpg_0","securityMode":2,"suppressSecOpErr":false,"overallState":1,"links":[{"href":"https://192.168.67.6:8080/api/v1/filestores/14b1451a-996a-4d95-b2f0-0bf6840ec423-6","rel":"self"},{"href":"https://192.168.67.6:8080/api/v1/fpgs?query=\"name EQ DockerFpg_0\"","rel":"fpg"},{"href":"https://192.168.67.6:8080/api/v1/virtualfileservers?query=\"name EQ DockerVfs_0 AND fpg EQ DockerFpg_0\"","rel":"virtualfileserver"},{"href":"https://192.168.67.6:8080/api/v1/fileshares?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ MySh_01\"","rel":"fileshares"},{"href":"https://192.168.67.6:8080/api/v1/filestoresnapshots?query=\"fpg EQ DockerFpg_0 AND vfs EQ DockerVfs_0 AND fstore EQ MySh_01\"","rel":"filestoresnapshots"}]}]}

2019-06-14 07:52:57,210 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 REQ: curl -i https://192.168.67.6:8080/api/v1/credentials/0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d DELETE -H "X-Hp3Par-Wsapi-Sessionkey: 0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d" -H "User-Agent: python-3parclient" -H "Accept: application/json"

2019-06-14 07:52:57,251 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP:{'Date': 'Fri, 14 Jun 2019 08:21:04 GMT' 'Server': 'hp3par-wsapi' 'Cache-Control': 'no-cache' 'Pragma': 'no-cache' 'Connection': 'close' 'status': '200' 'content-location': 'https://192.168.67.6:8080/api/v1/credentials/0-7a14958d5b1830cd0eddfd56dbae402f-ee58035d'}

2019-06-14 07:52:57,252 [DEBUG] hpe3parclient.http [140636216802024] Thread-20 RESP BODY:

2019-06-14 07:52:57,253 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-20 Try unlocking name DEFAULT/SHASHI-CPG/DockerFpg_0 2019-06-14 07:52:57,253 [DEBUG] etcd.client [140636216802024] Thread-20 Deleting /fp-fpg-lock/DEFAULT/SHASHI-CPG/DockerFpg_0 recursive=None dir=None extra args={} 2019-06-14 07:52:57,253 [DEBUG] etcd.client [140636216802024] Thread-20 Calculated params = {} 2019-06-14 07:52:57,255 [DEBUG] hpedockerplugin.etcdutil [140636216802024] Thread-20 Name is unlocked : DEFAULT/SHASHI-CPG/DockerFpg_0

leenaj0hn commented 5 years ago

logs: could not paste the file here. So pasted the snippet. Also the curl commands gave a "Network" error.

Created it on default FPG itself, but ensured that DockerFpg_0 have only one share( the share I created remaining) So final output on the array looks like this CSSOS-SSA06 cli% showfpg ------(GiB)------- FPG ---Mountpath---- --Size-- Available ActiveStates -DefaultCpg- -------VVs------- State Version DockerFpg_0 /DockerFpg_0 16384.00 16375.53 ACTIVATED swap_fs_cpg DockerFpg_0.1 normal 12.3 new_docker /new_docker 16384.00 16375.57 ACTIVATED swap_fs_cpg new_docker.1 normal 12.3 sandesh_new_fpg /sandesh_new_fpg 16384.00 16375.53 ACTIVATED swap_fs_cpg sandesh_new_fpg.1 normal 12.3 swap_fpg2 /swap_fpg2 16384.00 16375.53 ACTIVATED swap_fs_cpg swap_fpg2.1 normal 12.3

          4 total            65536.00  65502.16

CSSOS-SSA06 cli% showvfs VFS FPG IPAddr State -----Comment------ sandesh_new_fpg_vfs sandesh_new_fpg 192.168.110.2 normal Docker created VFS swap_fpg2_vfs swap_fpg2 192.168.110.7 normal Docker created VFS DockerVfs_0 DockerFpg_0 192.168.110.5 normal Docker created VFS

              3 total

CSSOS-SSA06 cli% showfshare ShareName Protocol VFS FileStore ShareDir State doc_share1 nfs sandesh_new_fpg_vfs doc_share1 ./ normal pvfile-first nfs sandesh_new_fpg_vfs pvfile-first ./ normal pvfile-two nfs sandesh_new_fpg_vfs pvfile-two ./ normal SH101 nfs swap_fpg2_vfs SH101 ./ normal share_im_1 nfs swap_fpg2_vfs share_im_1 ./ normal

imran-ansari commented 5 years ago

@leenaj0hn - Can u please clean up your ETCD and try this again?

prablr79 commented 5 years ago

@leenaj0hn any update on this bug ? are you still seeing this bug ?

imran-ansari commented 5 years ago

Had asked test team to reproduce it which they did successfully... Already created PR https://github.com/hpe-storage/python-hpedockerplugin/pull/666 with the fix for it.

Attached are the logs and docker output provided by the test team: BUG-648-log.txt

docker and 3par output of mount share.txt

wdurairaj commented 5 years ago

Please use the 3.2 tag of hpestorage/hpedockervolumeplugin:3.2 hpestorage/legacyvolumeplugin:3.2

sonawane-shashikant commented 5 years ago

This bug is VERIFIED as FIXED and can be closed.

Test Bed - [root@master-node ~]# cat /etc/redhat-release CentOS Linux release 7.6.1810 (Core) [root@master-node ~]#

CSIM_EOS14_1674003 cli% showversion -b Release version 3.3.1.460 (MU3) Patches: None 3PAR - 10.50.3.24 Component Name Version CLI Server 3.3.1.460 (MU3) CLI Client 3.3.1.460 System Manager 3.3.1.460 (MU3) Kernel 3.3.1.460 (MU3) TPD Kernel Code 3.3.1.460 (MU3) CSIM_EOS14_1674003 cli%

[root@master-node ~]# docker ps| grep plugin 94598363d0ce hpestorage/legacyvolumeplugin:3.2 "/bin/sh -c ./plug..." 2 hours ago Up About an hour plugin_container [root@master-node ~]#

DOCKER OUTPUT:

[root@master-node ~]# docker volume create -d hpe --name SHARE01 -o filePersona SHARE01 [root@master-node ~]# docker volume inspect SHARE01 [ { "Driver": "hpe", "Labels": {}, "Mountpoint": "/", "Name": "SHARE01", "Options": { "filePersona": "" }, "Scope": "global", "Status": { "backend": "DEFAULT_FILE", "clientIPs": [], "cpg": "SHASHI_CPG", "fpg": null, "fsMode": null, "fsOwner": null, "name": "SHARE01", "protocol": "nfs", "sharePath": null, "size": "1024 GiB", "status": "CREATING", "vfs": null } } ] [root@master-node ~]# docker volume inspect SHARE01 [ { "Driver": "hpe", "Labels": {}, "Mountpoint": "/", "Name": "SHARE01", "Options": { "filePersona": "" }, "Scope": "global", "Status": { "backend": "DEFAULT_FILE", "clientIPs": [], "cpg": "SHASHI_CPG", "fpg": "DockerFpg_0", "fsMode": null, "fsOwner": null, "name": "SHARE01", "protocol": "nfs", "sharePath": "10.50.9.231:/DockerFpg_0/DockerVfs_0/SHARE01", "size": "1024 GiB", "status": "AVAILABLE", "vfs": "DockerVfs_0", "vfsIPs": [ [ "10.50.9.231", "255.255.255.0" ] ] } } ] [root@master-node ~]# ping 10.50.9.231 PING 10.50.9.231 (10.50.9.231) 56(84) bytes of data. 64 bytes from 10.50.9.231: icmp_seq=1 ttl=64 time=0.294 ms 64 bytes from 10.50.9.231: icmp_seq=2 ttl=64 time=0.187 ms 64 bytes from 10.50.9.231: icmp_seq=3 ttl=64 time=0.159 ms 64 bytes from 10.50.9.231: icmp_seq=4 ttl=64 time=0.183 ms ^C --- 10.50.9.231 ping statistics --- 4 packets transmitted, 4 received, 0% packet loss, time 3004ms

[root@master-node ~]# docker run -it -d -v SHARE01:/data --volume-driver hpe --rm busybox /bin/sh 128932f67db6f5421a5118a7bc5cae595fb12609aa8fb72787771e98a5a27e05 [root@master-node ~]# docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 128932f67db6 busybox "/bin/sh" 21 seconds ago Up 13
plugin_container c70b2eda39e0 quay.io/coreos/etcd:v2.2.0 "/etcd -name etcd0..." 2 hours ago Up 2 hours 2379-2380/tcp, 4001/tcp, 0.0.0.0:23790->23790/tcp, 0.0.0.0:23800->23800/tcp, 7001/tcp, 0.0.0.0:40010->40010/tcp etcd

[root@master-node ~]# docker attach 128932f67db6 / # cd data/ /data # mkdir shashi /data # cd shashi/ /data/shashi # echo "This is verification of issues number 648" > shashi.txt /data/shashi # cat shashi.txt This is verification of issues number 648 /data/shashi # read escape sequence

[root@master-node ~]# docker ps | grep busy 128932f67db6 busybox "/bin/sh" About a minute ago Up About a minute jovial_jones

[root@master-node ~]# docker volume rm SHARE01 Error response from daemon: unable to remove volume: remove SHARE01: volume is in use - [128932f67db6f5421a5118a7bc5cae595fb12609aa8fb72787771e98a5a27e05]

[root@master-node ~]# docker stop 128932f67db6 128932f67db6 [root@master-node ~]# docker ps | grep busy [root@master-node ~]# docker volume rm SHARE01 SHARE01 [root@master-node ~]# docker volume ls DRIVER VOLUME NAME [root@master-node ~]#

3par output:

CSIM_EOS14_1674003 cli% showfpg ------(GiB)------- FPG -Mountpath-- --Size-- Available ActiveStates -DefaultCpg- -----VVs----- State Version DockerFpg_0 /DockerFpg_0 16384.00 16375.54 ACTIVATED SHASHI_CPG DockerFpg_0.1 normal 12.3 DockerFpg_1 /DockerFpg_1 16384.00 16375.54 ACTIVATED sandesh DockerFpg_1.1 normal 12.3

      2 total        32768.00  32751.08

CSIM_EOS14_1674003 cli% showvfs VFS FPG IPAddr State -----Comment------ DockerVfs_1 DockerFpg_1 10.50.9.48 normal Docker created VFS DockerVfs_0 DockerFpg_0 10.50.9.231 normal Docker created VFS

      2 total

CSIM_EOS14_1674003 cli% showfshare ShareName Protocol VFS FileStore ShareDir State FIX-FOR-648_VERIFY nfs DockerVfs_1 FIX-FOR-648_VERIFY ./ normal SHARE01 nfs DockerVfs_0 SHARE01 ./ normal

             2 total

CSIM_EOS14_1674003 cli% showfpg ------(GiB)------- FPG -Mountpath-- --Size-- Available ActiveStates -DefaultCpg- -----VVs----- State Version DockerFpg_0 /DockerFpg_0 16384.00 16375.54 ACTIVATED SHASHI_CPG DockerFpg_0.1 normal 12.3 DockerFpg_1 /DockerFpg_1 16384.00 16375.54 ACTIVATED sandesh DockerFpg_1.1 normal 12.3

      2 total        32768.00  32751.08

CSIM_EOS14_1674003 cli% showvfs VFS FPG IPAddr State -----Comment------ DockerVfs_0 DockerFpg_0 10.50.9.231 normal Docker created VFS DockerVfs_1 DockerFpg_1 10.50.9.48 normal Docker created VFS

      2 total

CSIM_EOS14_1674003 cli% showfshare ShareName Protocol VFS FileStore ShareDir State FIX-FOR-648_VERIFY nfs DockerVfs_1 FIX-FOR-648_VERIFY ./ normal

             1 total

CSIM_EOS14_1674003 cli% showfstore ------Security------ Fstore VFS FPG State Mode ErrorSuppress -Comment- .admin DockerVfs_1 DockerFpg_1 normal legacy false FIX-FOR-648_VERIFY DockerVfs_1 DockerFpg_1 normal legacy false

             2 total

CSIM_EOS14_1674003 cli% showfpg ------(GiB)------- FPG -Mountpath-- --Size-- Available ActiveStates -DefaultCpg- -----VVs----- State Version DockerFpg_1 /DockerFpg_1 16384.00 16375.54 ACTIVATED sandesh DockerFpg_1.1 normal 12.3

      1 total        16384.00  16375.54

CSIM_EOS14_1674003 cli% showvfs VFS FPG IPAddr State -----Comment------ DockerVfs_1 DockerFpg_1 10.50.9.48 normal Docker created VFS

      1 total

Attaching log captured while verification

Bug_648_Verify.docx 648_VERIFICATION_LOG.txt

amitk1977 commented 5 years ago

Closing as per Shashi