23 minutes for deleting one asd

[jeroenmaelbrancke]

Problem

It takes 23 minutes on Nuvolat to delete one disk on a local backend

Start of the deletion

2018-05-03 09:20:25 89100 -0400 - NY1SRV0040 - 18418/140293476120320 - asd-manager/api - 2871 - INFO - POST /disks/<disk_id>/asds/<asd_id>/delete - Entering with [] {"asd_id": "3wTsLtdmVL8XiotcfzgC4m6sqYRfYNzX", "disk_id": "scsi-35000cca25d214ed8"}

After 18 minutes the timeout of the client is here:

2018-05-03 09:38:32 88800 -0400 - NY1SRV0040 - 18418/140293476120320 - asd-manager/api - 3112 - DEBUG - POST /disks/<disk_id>/asds/<asd_id>/delete - Leaving
Traceback (most recent call last):
  File "/usr/lib/python2.7/SocketServer.py", line 596, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python2.7/SocketServer.py", line 331, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python2.7/SocketServer.py", line 654, in __init__
    self.finish()
  File "/usr/lib/python2.7/SocketServer.py", line 713, in finish
    self.wfile.close()
  File "/usr/lib/python2.7/socket.py", line 283, in close
    self.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/ssl.py", line 743, in sendall
    v = self.send(data[count:])
  File "/usr/lib/python2.7/ssl.py", line 709, in send
    v = self._sslobj.write(data)
error: [Errno 32] Broken pipe
----------------------------------------
Exception happened during processing of request from ('172.17.16.22', 44744)

While the task already have been failed with None, None after 2 minutes

May  3 09:22:25 NY1SRV0019 celery[18958]: 2018-05-03 09:22:25 95300 -0400 - NY1SRV0019 - 18958/139895573935872 - celery/celery.worker.job - 872 - ERROR - Task albanode.reset_asd[0cea647c-fd47-4712-b846-cbeaef51156e] raised unexpected: ReadTimeout(ReadTimeoutError('None: None',),)
May  3 09:22:25 NY1SRV0019 celery[18958]: Traceback (most recent call last):
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/celery/app/trace.py", line 240, in trace_task
May  3 09:22:25 NY1SRV0019 celery[18958]:     R = retval = fun(*args, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/celery/app/trace.py", line 438, in __protected_call__
May  3 09:22:25 NY1SRV0019 celery[18958]:     return self.run(*args, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/opt/OpenvStorage/ovs/lib/albanode.py", line 368, in reset_asd
May  3 09:22:25 NY1SRV0019 celery[18958]:     expected_safety=expected_safety)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/celery/local.py", line 188, in __call__
May  3 09:22:25 NY1SRV0019 celery[18958]:     return self._get_current_object()(*a, **kw)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/celery/app/trace.py", line 439, in __protected_call__
May  3 09:22:25 NY1SRV0019 celery[18958]:     return orig(self, *args, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/celery/app/task.py", line 420, in __call__
May  3 09:22:25 NY1SRV0019 celery[18958]:     return self.run(*args, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/opt/OpenvStorage/ovs/lib/helpers/decorators.py", line 461, in new_function
May  3 09:22:25 NY1SRV0019 celery[18958]:     output = f(*args, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/opt/OpenvStorage/ovs/lib/albanode.py", line 326, in remove_asd
May  3 09:22:25 NY1SRV0019 celery[18958]:     asd_id=asd_id)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/opt/OpenvStorage/ovs/extensions/plugins/asdmanager.py", line 226, in delete_asd
May  3 09:22:25 NY1SRV0019 celery[18958]:     return self._call(requests.post, 'disks/{0}/asds/{1}/delete'.format(disk_id, asd_id), timeout=120)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/opt/OpenvStorage/ovs/extensions/plugins/asdmanager.py", line 95, in _call
May  3 09:22:25 NY1SRV0019 celery[18958]:     response = method(**kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/requests/api.py", line 107, in post
May  3 09:22:25 NY1SRV0019 celery[18958]:     return request('post', url, data=data, json=json, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/requests/api.py", line 53, in request
May  3 09:22:25 NY1SRV0019 celery[18958]:     return session.request(method=method, url=url, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/requests/sessions.py", line 468, in request
May  3 09:22:25 NY1SRV0019 celery[18958]:     resp = self.send(prep, **send_kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/requests/sessions.py", line 576, in send
May  3 09:22:25 NY1SRV0019 celery[18958]:     r = adapter.send(request, **kwargs)
May  3 09:22:25 NY1SRV0019 celery[18958]:   File "/usr/lib/python2.7/dist-packages/requests/adapters.py", line 449, in send
May  3 09:22:25 NY1SRV0019 celery[18958]:     raise ReadTimeout(e, request=request)
May  3 09:22:25 NY1SRV0019 celery[18958]: ReadTimeout: None: None

[JeffreyDevloo]

The removal must have gone a bit quicker. Replacing the OSD might have been taking longer (the MKFS thing)

[jeroenmaelbrancke]

Well the mkfs thing was a mistake this is only happening when i create a new ASD.
What i don't understand is the service file has been deleted but the framework doesn't get notified by that.

Will running the asd-manager in debug mode help us or not?