Bug 1270220

The following is seen in vdsm.log

14:39:18,242::task::866::Storage.TaskManager.Task::(_setError) Task=`<id>`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 1545, in deleteImage
    pool.deleteImage(dom, imgUUID, volsByImg)
  File "/usr/share/vdsm/storage/securable.py", line 77, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/share/vdsm/storage/sp.py", line 1869, in deleteImage
    domain.deleteImage(domain.sdUUID, imgUUID, volsByImg)
  File "/usr/share/vdsm/storage/fileSD.py", line 384, in deleteImage
    self.oop.os.remove(volPath)
  File "/usr/share/vdsm/storage/outOfProcess.py", line 245, in remove
    self._iop.unlink(path)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 455, in unlink
    return self._sendCommand("unlink", {"path": path}, self.timeout)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 385, in _sendCommand
    raise Timeout(os.strerror(errno.ETIMEDOUT))
Timeout: Connection timed out

Which then later is propagated to the manager, after the task is aborted
Thread-858705::ERROR::2015-10-07 14:39:18,304::dispatcher::79::Storage.Dispatcher::(wrapper) Connection timed out
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
    return m(self, *a, **kw)
  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
    raise self.error
Timeout: Connection timed out
Thread-858705::DEBUG::2015-10-07 14:39:18,307::stompReactor::163::yajsonrpc.StompServer::(send) Sending response

Also seen with glob:
Thread-847559::ERROR::2015-10-07 10:31:00,791::task::866::Storage.TaskManager.Task::(_setError) Task=`id`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 1515, in deleteImage
    allVols = dom.getAllVolumes()
  File "/usr/share/vdsm/storage/fileSD.py", line 425, in getAllVolumes
    volMetaPaths = self.oop.glob.glob(volMetaPattern)
  File "/usr/share/vdsm/storage/outOfProcess.py", line 120, in glob
    return self._iop.glob(pattern)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 500, in glob
    return self._sendCommand("glob", {"pattern": pattern}, self.timeout)
  File "/usr/lib/python2.6/site-packages/ioprocess/__init__.py", line 385, in _sendCommand
    raise Timeout(os.strerror(errno.ETIMEDOUT))
Timeout: Connection timed out

which then gets propagated as well, after task is aborted
Thread-847559::ERROR::2015-10-07 10:31:00,800::dispatcher::79::Storage.Dispatcher::(wrapper) Connection timed out
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
    return m(self, *a, **kw)
  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
    raise self.error
Timeout: Connection timed out
Thread-847559::DEBUG::2015-10-07 10:31:00,801::stompReactor::163::yajsonrpc.StompServer::(send) Sending response

Nir, can you take a look and see if there's anything intelligent we can do here?

Tim, can you check if using rfh oop implementation works better for this case?

ioprocess should be better in any way, but it is new and less tested than rfh.

To switch implementation edit /etc/vdsm.conf and set:

[irs]
oop_impl = rfh

Restart vdsm to apply the change.

(In reply to Tim Speetjens from comment #0)
> Description of problem:
> When under load, 

Can you be more specific about "under load"? how can we reproduce this
load?

> NFS filers may require a very large time 

What is very large time? How much time it takes to delete files in this
case?

> to delete large
> files. When this happens, the SPM status is set to problematic, and messages
> are seen saying 'Data Center is being initialized'

> Expected results:
> The SPM should be more tolerant on slow deletes, and continue its operations
> without issues.

We can increase the timeouts calling ioprocess, but this will lead to tasks
that are blocked for long time, and we have a limit on the number of 
concurrent tasks (10), and number of queued tasks (500). Increasing the
timeouts would probably require increasing the other limits as well.

> Additional info:
> When this happens, manual cleanup is required: ex. Locked disks, locked
> disks,  disks in illegal state

This looks like an engine issue. engine should be prepared for handling 
failed deletes, retrying the operation or allowing the user to retry.
Can you open a separate engine bug for this?

If you want to try larger timeouts:

[irs]
process_pool_timeout = 60
process_pool_max_slots_per_domain = 10
process_pool_max_queued_slots_per_domain = 10
thread_pool_size = 10
max_tasks = 500

Start with increasing process_pool_timeout (e.g. 120), and lets see if this
change is good enough.

You may need to increase thread_pool_size, which may need an increase of 
process_pool_max_slots_per_domain.

Checking the relevant code reveal that deleteImage is a synchronous 
operation since pre 2.3 (a comment mention that this should be fixed in
2.3).

When using "wipe after delete" (only relevant to block storage), we 
perform the validation in the request thread, and the actual delete in
the task manager.

In file storage and block storage when not using "wipe after delete", the 
entire operation is performed in the request thread, and the "task" 
scheduled is only a fake task for error reporting.

This means that tuning task manager configuration (e.g. thread_pool_size)
will have no effect on this issue.

Also, since there is no limit on the number of request threads, the 
operation may fail since there are no available oop handlers. This
problem is worse with jsonrpc since it may create unlimited number
of request threads, while with xmlrpc, there is a thread per engine
connection.

Changing this design is too risky for 3.5, and is too late for 3.6.

The new SDM code should avoid this issue by running delete operations
in a thread pool, and by the new garbage collection mechanism.

I think we should target this to new SDM feature.

For 3.5, we can consider tuning of the timeouts, although I don't think we
can ship extreme timeouts that work with very slow nfs server. Handling
such case must be by site specific configuration until the issue on the 
server side is resolved by the vendor.

Adam, what do you think?

(In reply to Nir Soffer from comment #6)
> If you want to try larger timeouts:

> Start with increasing process_pool_timeout (e.g. 120), and lets see if this
> change is good enough.

From our investigations, the largest time it took for the unlink system call, was about 90 seconds. (Later this even grew larger) Based on this, we already set the process_pool_timeout to 180.

This wasn't sufficient, as the unlink system calls that took about 60 seconds, still would make the proces_pool_timeout to be reached with the "unlink" command in ioprocess.

Do we have any other bottlenecks, in this mechanism?

> Also, since there is no limit on the number of request threads, the 
> operation may fail since there are no available oop handlers. This
> problem is worse with jsonrpc since it may create unlimited number
> of request threads, while with xmlrpc, there is a thread per engine
> connection.

Also, tests were performed with, in addition to the 180 seconds timeout, a process_pool_max_slots_per_domain of 20. These values, still do not prevent the issue, however, it may have had a positive impact.

Can we measure this? For example: how long do the oop requests take, what's the state of the ioprocess thread pool?

(In reply to Tim Speetjens from comment #8)
> (In reply to Nir Soffer from comment #6)
> > If you want to try larger timeouts:
> 
> > Start with increasing process_pool_timeout (e.g. 120), and lets see if this
> > change is good enough.
> 
> From our investigations, the largest time it took for the unlink system
> call, was about 90 seconds. (Later this even grew larger) Based on this, we
> already set the process_pool_timeout to 180.
> 
> This wasn't sufficient, as the unlink system calls that took about 60
> seconds, still would make the proces_pool_timeout to be reached with the
> "unlink" command in ioprocess.

You set process_pool_timeout to 180, but an unlink that took 60 caused a timeout?

> Do we have any other bottlenecks, in this mechanism?

Maybe there is some hardcoded timeout in ioprocess.

Piotr, can you check this?

> > Also, since there is no limit on the number of request threads, the 
> > operation may fail since there are no available oop handlers. This
> > problem is worse with jsonrpc since it may create unlimited number
> > of request threads, while with xmlrpc, there is a thread per engine
> > connection.
> 
> Also, tests were performed with, in addition to the 180 seconds timeout, a
> process_pool_max_slots_per_domain of 20. These values, still do not prevent
> the issue, however, it may have had a positive impact.
> 
> Can we measure this? For example: how long do the oop requests take, what's
> the state of the ioprocess thread pool?

Piotr, can you answer this?

I am not aware of any hardcoded timeouts.

(In reply to Nir Soffer from comment #7)
> Checking the relevant code reveal that deleteImage is a synchronous 
> operation since pre 2.3 (a comment mention that this should be fixed in
> 2.3).
> 
> When using "wipe after delete" (only relevant to block storage), we 
> perform the validation in the request thread, and the actual delete in
> the task manager.

wipe after delete is not really an operation on NFS, AFAIR.
And delete itself should be a very quick operation.

Tim, how many concurrent deleteImage tasks can you see in vdsm log, and how many tasks where running in vdsm when you had the timeouts?

If storage is very slow, all iprocess threads may be busy waiting for the
storage, and new io requests can time out waiting in ioprocess queue.

If this is the case, increasing "process_pool_max_slots_per_domain" can
help. I would try to increase this value to 20 or 30.

Tim, we will track the ioprocess issues in bug 1273122.

Please check this bug and add more info if needed.

We've simulated customer case using a 3.5 setup with vdsm-4.16.20-1.el6ev.x86_64 installed on host.
I used NFS storage server with Nir's code that simulates a slow file system.


I created VM from template as clone (1 image - 3 files/volumes under the image dir)

Modified the following:

engine:
VdsTimeout=900


vdsm.conf:
[irs]
process_pool_max_slots_per_domain = 20
process_pool_timeout = 100

Removed the VM with its disk.

deleteImage starts:

Thread-267::INFO::2015-10-21 16:56:53,608::logUtils::44::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='f1260a63-d301-465d-a41e-a1986c6f702a', spUUID='00000002-0002-0002-0002-000000000152', imgUUID='5636bc19-c1a8-4218-a5c3-5e5fa0da9b9a', postZero='false', force='false')


Thread-267::DEBUG::2015-10-21 16:56:53,609::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.5636bc19-c1a8-4218-a5c3-5e5fa0da9b9a_f1260a63-d301-465d-a41e-a1986c6f702a`ReqID=`40d9f7d7-06c5-46ef-a4ed-5c33e75bcab2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1513' at 'deleteImage'

Dir rename:

Thread-267::DEBUG::2015-10-21 16:56:53,651::fileSD::374::Storage.StorageDomain::(deleteImage) Renaming dir /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/5636bc19-c1a8-4218-a5c3-5e5fa0da9b9a to /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remor3eg5J

volume removal starts:

Thread-267::DEBUG::2015-10-21 16:56:53,654::fileSD::383::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remor3eg5J/28211c7b-108b-444a-a843-d571f73d3e67

meta file removal starts:

Thread-267::DEBUG::2015-10-21 16:58:23,786::fileSD::386::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remor3eg5J/28211c7b-108b-444a-a843-d571f73d3e67.meta

lease file removal starts:

Thread-267::DEBUG::2015-10-21 16:59:53,940::fileSD::389::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remor3eg5J/28211c7b-108b-444a-a843-d571f73d3e67.lease


Dir removal:

Thread-267::DEBUG::2015-10-21 17:01:24,027::fileSD::394::Storage.StorageDomain::(deleteImage) Removing directory: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remor3eg5J

deleteImage ends successfully:

Thread-267::INFO::2015-10-21 17:01:24,166::logUtils::47::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None

*Tested while the delay in the storage server for each remove operation is set to 90 seconds.

Tested with the following conf:

Slowfs conf:
unlink = 45

engine conf:
VdsTimeout = 360

vdsm.conf:
[irs]
process_pool_max_slots_per_domain = 20
process_pool_timeout = 60

Created 50 VM with one 1G sparse disk on the slowfs domain.
Then removed the disks using python sdk (done one by one by the system)

All vms were removed successfully, no timeouts seen in vdsm log.

Example delete flow:

Thread-3097::INFO::2015-10-22 13:59:53,885::logUtils::44::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='f1260a63-d301-465d-a41e-a1986c6f702a', spUUID='00000002-0002-0002-0002-000000000152', imgUUID='0
a787408-e5c3-43ec-a1ba-3c5bc9e6abb2', postZero='false', force='false')

Thread-3097::DEBUG::2015-10-22 13:59:53,910::fileSD::374::Storage.StorageDomain::(deleteImage) Renaming dir /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/0a7874
08-e5c3-43ec-a1ba-3c5bc9e6abb2 to /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remoyEOMTo

Thread-3097::DEBUG::2015-10-22 13:59:53,912::fileSD::383::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_rem
oyEOMTo/72b5ecbe-75d6-4f03-8961-cacc40d35fd9

meta file removal:

Thread-3097::DEBUG::2015-10-22 14:00:38,962::fileSD::386::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remoyEOMTo/72b5ecbe-75d6-4f03-8961-cacc40d35fd9.meta
Thread-3097::DEBUG::2015-10-22 14:01:24,030::fileSD::389::Storage.StorageDomain::(deleteImage) Removing file: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remoyEOMTo/72b5ecbe-75d6-4f03-8961-cacc40d35fd9.lease

Thread-3097::DEBUG::2015-10-22 14:02:09,084::fileSD::394::Storage.StorageDomain::(deleteImage) Removing directory: /rhev/data-center/mnt/10.35.161.79:_root_test_slowfs_1/f1260a63-d301-465d-a41e-a1986c6f702a/images/_remoyEOMTo

Thread-3097::INFO::2015-10-22 14:02:09,163::logUtils::47::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None

Tim,

To get logs from ioprocess, you also must enable DEBUG logs in ioprocess
logger in vdsm.conf:

#/etc/vdsm/logger.conf

[logger_IOProcess]
level=DEBUG
handlers=logfile
qualname=IOProcess
propagate=0

Restart vdsm to apply the changes.

We are waiting now for new logs from customer, showing vdsm timeouts with
ioprocess timing info.

Thanks,
Nir

Elad - please note that the customer's VMs are large, may or may not be sparse, and there are many. We believe that deleting large disks is significantly different than 1G ones. Please try with with much larger disks.

Yaniv, the test we've performed simulated a long files deletion (each disk deletion took around 3 minutes) which supposed to be similar to a large disks deletion over non-delayed storage.
Also, I need some more information from GSS.

Tim, can you please provide the exact setup specification of the customer, I would like to know the following:
1) Were the VMs created as thin copy or cloned from the template? (i.e, are the VMs disks are independent/cloned or thin/snapshots?)
2) The amount of VMs and disks.

In terms of disks size, the allocation policy of the disks is not relevant since we're talking about file based storage. Nir, can you confirm?

(In reply to Elad from comment #31)
> In terms of disks size, the allocation policy of the disks is not relevant
> since we're talking about file based storage. Nir, can you confirm?

Yes

(In reply to Nir Soffer from comment #32)
> (In reply to Elad from comment #31)
> > In terms of disks size, the allocation policy of the disks is not relevant
> > since we're talking about file based storage. Nir, can you confirm?
> 
> Yes

I'm not sure if raw-sparse and qcow2 will behave the same on NFS. Files are files, but they allocation underneath and the way the FS treats them may be different.

(In reply to Yaniv Kaul from comment #33)
> (In reply to Nir Soffer from comment #32)
> > (In reply to Elad from comment #31)
> > > In terms of disks size, the allocation policy of the disks is not relevant
> > > since we're talking about file based storage. Nir, can you confirm?
> > 
> > Yes
> 
> I'm not sure if raw-sparse and qcow2 will behave the same on NFS. Files are
> files, but they allocation underneath and the way the FS treats them may be
> different.

Yes, but we tested deletion of empty files, so the format does not matter.

To be more specific about how we tested - we used nfs server exporting slowfs filesystem[1]. We configure unlink to take at least 45 seconds, regardless of the size of file unlinked (slowfs sleeps 45 before unlinking
the file, blocking the caller).

Since each disk deleted has 3 volumes (image/volume, image/volume.meta, image/volume.lease), delete took at least 135 seconds, as we can see in 
the example flow in comment 28.

We can check the effect of deleting big files with different allocation
with a real filesystem, but I don't think this is the issue here. The
users are creating and deleting vm for each test, so it does not make 
sense to copy big images and delete them for each vm.

In the logs added in comment 23 and comment 24, we can see that the user 
is deleting 232 vms during 2 hours.

I suggest to wait for more info from Tim, about the file size and format
of the failed deletes.

[1] https://github.com/nirs/slowfs

Currently there no immediate solution in sight and since the 3.5.6 build is tomorrow targeting to 3.5.7

Currently, deleteImage on file based storage is renaming the image to _remove_me_XXXXX (XXXXXX is random name), then remove all the files in the image directory and finally remove empty image directory.

While vdsm is busy removing image files, engine is holding the spm lock and waiting until the operation is finished. No other spm operation can happen during this time.

This design is a weak point in the system, and plan to improve it in 3.6.
Hopefully we will be able to backport a fix to 3.5 or at least provide
a hotfix for users that have issues with the current design.

Our plan is to modify deleteImage on file based storage so it works more 
like block storage:

1. rename the image directory to _remove_me_XXXX
2. schedule removal of the volumes in the task manager
3. return success

Engine will remove the image from the database at this point, and will be able to send the next SPM command immediately.

The actual removal of the image files will happen later in a task manager
thread.

We assume that most delete operation are fast, so in the worst case, some
threads in the task manager will be blocked for couple of minutes on slow 
deletes, without effecting other tasks.

In the worst case, all tasks will be blocked on slow deletes until they
time out. In this case, stale _remove_me_XXXXXX directories can be removed
manually. We have the same issue in block storage if the wipe after delete
fails. This issue will be solved in 4.0 which will use a different scheme
where engine control the process, and no stale files will be left on
storage.

Tim, we would like to get your input before we continue with this plan.

Sahina, is this plan going to work with gluster storage domain? We assume
that rename is atomic (posix requirment) and fast.

Is rename on gluster storage fast and atomic?

I would prefer to have both rename and delete in the async task, managed by task manager, but I'm ok with the proposed solution.

(In reply to Tim Speetjens from comment #39)
> I would prefer to have both rename and delete in the async task, managed by
> task manager, but I'm ok with the proposed solution.

Tim, this may be possible in the next version, but for 3.6/3.5, we want
minimal changes.

*** Bug 1266579 has been marked as a duplicate of this bug. ***

(In reply to Nir Soffer from comment #38)
> Sahina, is this plan going to work with gluster storage domain? We assume
> that rename is atomic (posix requirment) and fast.
> 
> Is rename on gluster storage fast and atomic?

Nir, as per Raghavendra (rgowdappa) from gluster team :

1. rename of files (non-directories) is atomic. We hold a lock which contends with other renames on the same file. However, this lock doesn't prevent other directory operations like readdir, creating/deleting links to the same file etc while rename is being done.
2. Directory renames are non-atomic and there is no crash-consistency.
3. There is no roll-back/crash-consistency in rename. rename is a compound operation in gluster DHT layer. Though we acquire lock, if there is a crash of brick/client, rollback is not performed. So, future operations can "see" intermediate state of rename. (However for a replicate only volume, rename of directories is atomic)

AFAIK, the urgent customer issue was solved onsite and was caused due to a misconfiguration of an NFS Filer. 

The proposed patch touches a very delicate area of the code, and since there appears to be no real urgency, I'm delaying it to 4.0.
If this becomes urgent again, we can always reschedule.

Liron, the patch is merged for ovirt's master (the would-be 4.0).
Is there anything else we're waiting for, or can this be moved to MODIFIED?

moved to MODIFIED

Hi Nir, Liron,

Using slowfs [1], I simulated a slow files deletion (unlink = 30).
I removed 10 images with several volumes (snapshots) each (~5 each). 
Several deleteImage tasks were opened and executed simultaneity by the SPM :


[root@purple-vds1 images]# vdsClient -s 0 getAllTasks
0699484c-dd65-46a7-8a47-b47d180682ec :
         verb = deleteImage
         code = 0
         state = running
         tag = spm
         result = 
         message = running job 1 of 1
         id = 0699484c-dd65-46a7-8a47-b47d180682ec
248170d2-ee01-4b35-bf2c-914fe5730994 :
         verb = deleteImage
         code = 0
         state = running
         tag = spm
         result = 
         message = running job 1 of 1
         id = 248170d2-ee01-4b35-bf2c-914fe5730994
d352c6ca-a1ea-4a60-a3df-84c6f6e34b90 :
         verb = deleteImage
         code = 100
         state = recovered
         tag = spm
         result = 
         message = Connection timed out
         id = d352c6ca-a1ea-4a60-a3df-84c6f6e34b90
cf56ab7d-772c-4994-b463-a2068501885b :
         verb = deleteImage
         code = 0
         state = running
         tag = spm
         result = 
         message = running job 1 of 1
         id = cf56ab7d-772c-4994-b463-a2068501885b
3f1233fc-8db5-4c94-ad75-8edfed545f08 :
         verb = deleteImage
         code = 0
         state = finished
         tag = spm
         result = 
         message = 1 jobs completed successfully
         id = 3f1233fc-8db5-4c94-ad75-8edfed545f08


Thread-2133::INFO::2016-04-26 15:10:43,243::logUtils::52::dispatcher::(wrapper) Run and protect: getAllTasks, Return response: {'tasks': {'cf56ab7d-772c-4994-b463-a2068501885b': {'code': 0, 'tag': u'spm', 'state':
 'running', 'verb': 'deleteImage', 'result': '', 'message': 'running job 1 of 1', 'id': 'cf56ab7d-772c-4994-b463-a2068501885b'}, 'd352c6ca-a1ea-4a60-a3df-84c6f6e34b90': {'code': 100, 'tag': u'spm', 'state': 'recov
ered', 'verb': 'deleteImage', 'result': '', 'message': u'Connection timed out', 'id': 'd352c6ca-a1ea-4a60-a3df-84c6f6e34b90'}, '248170d2-ee01-4b35-bf2c-914fe5730994': {'code': 0, 'tag': u'spm', 'state': 'running',
 'verb': 'deleteImage', 'result': '', 'message': 'running job 1 of 1', 'id': '248170d2-ee01-4b35-bf2c-914fe5730994'}, '0699484c-dd65-46a7-8a47-b47d180682ec': {'code': 0, 'tag': u'spm', 'state': 'running', 'verb': 
'deleteImage', 'result': '', 'message': 'running job 1 of 1', 'id': '0699484c-dd65-46a7-8a47-b47d180682ec'}, '3f1233fc-8db5-4c94-ad75-8edfed545f08': {'code': 0, 'tag': u'spm', 'state': 'finished', 'verb': 'deleteI
mage', 'result': '', 'message': '1 jobs completed successfully', 'id': '3f1233fc-8db5-4c94-ad75-8edfed545f08'}}}



[1] https://github.com/nirs/slowfs/blob/master/README.md



Is this the desired behaviour? Can I verify?

Elad,
the patch in this bug reduces the execution time of the deleteImage() verb without harming its functionality.
to verify it properly, i'd suggest to make the deletion of files very slow (either by manipulating the vdsm code or by using slowfs) and attempt to reuse the disk id (for example - by importing it again) before the deletion is ended.

that way you could verify that no regression was introduced and as the syncronous part of the deletion ends the disk is considered to be deleted and its id is free to be used.

thanks,
Liron.

Created attachment 1151791 [details]
logs-28.4

Liron, Tired your suggestion in comment #48:
Created a NFS domain based on slowfs, created a VM with a disk resides on the slowfs domain attached, exported the VM to export domain, changed the deletion delay in the server to 10 sec (unlink = 10), removed the VM with the attached disk and immediately tried to import the VM with the disk (the same image ID).

This is what I got:

2016-04-28 12:44:01,823 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (default task-14) [338bff11] ERROR, GetImagesListVDSCommand( GetImagesListVDSCommandParameters:{runAsync='true', storagePoolId='7de10d80-b113-4f60-8f7f-e70f6476432b', ignoreFailoverLimit='false', sdUUID='fb97cea4-5bf2-48fa-9ceb-b8b2e109acd4'}), exception: For input string: "_remove_me_a9187951", log id: 6238e26f
2016-04-28 12:44:01,823 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (default task-14) [338bff11] Exception: java.lang.NumberFormatException: For input string: "_remove_me_a9187951"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) [rt.jar:1.8.0_71]
        at java.lang.Long.parseLong(Long.java:589) [rt.jar:1.8.0_71]
        at java.lang.Long.valueOf(Long.java:776) [rt.jar:1.8.0_71]
        at java.lang.Long.decode(Long.java:928) [rt.jar:1.8.0_71]
        at java.util.UUID.fromString(UUID.java:198) [rt.jar:1.8.0_71]
        at org.ovirt.engine.core.compat.Guid.<init>(Guid.java:73) [compat.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.GetImagesListVDSCommand.executeIrsBrokerCommand(GetImagesListVDSCommand.java:23) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.executeVDSCommand(IrsBrokerCommand.java:159) [vdsbroker.jar:]


============================

Webadmdin:


Operation Canceled

Error while executing action: 

slow:
General command validation failure.

============================

This might be a separate bug in engine.
Full logs attached.

Elad, that's a separate bug (3.6.7). lets open it.

thanks.

Thanks Liron

As you suggested offline, created a template and copied its disk to the slowfs domain. Then deleted the disk while 10 sec delay is configured for deletion and tried to copy the disk again to the slowfs domain. Image copy was initiated successfully while the old one was still under deletion process. Copy image finished successfully.

The same image exist twice on the domain (_remove_me_e83cb973-cc7b-4f03-94ce-8c4f21a9b683 and e83cb973-cc7b-4f03-94ce-8c4f21a9b683):

Every 2.0s: ls -l                                                                                                                                                 Thu Apr 28 13:38:17 2016

total 20
drwxr-xr-x. 2 root root 4096 Apr 28 13:01 9a813945-0af6-4228-bee3-8621ec4e351d
drwxr-xr-x. 2 root root 4096 Apr 28 13:01 b2df65ac-bfe4-4a56-a142-21f21ccb0023
drwxr-xr-x. 2 root root 4096 Apr 28 13:37 e83cb973-cc7b-4f03-94ce-8c4f21a9b683
drwxr-xr-x. 2 root root 4096 Apr 28 13:29 ef31097e-c317-4d58-b539-fcf82493e2d7
drwxr-xr-x. 2 root root 4096 Apr 28 13:38 _remove_me_e83cb973-cc7b-4f03-94ce-8c4f21a9b683


After deletion of _remove_me_e83cb973-cc7b-4f03-94ce-8c4f21a9b683 finished, only the new image exist (e83cb973-cc7b-4f03-94ce-8c4f21a9b683):

Every 2.0s: ls -l                                                                                                                                                 Thu Apr 28 13:41:52 2016

total 16
drwxr-xr-x. 2 root root 4096 Apr 28 13:01 9a813945-0af6-4228-bee3-8621ec4e351d
drwxr-xr-x. 2 root root 4096 Apr 28 13:01 b2df65ac-bfe4-4a56-a142-21f21ccb0023
drwxr-xr-x. 2 root root 4096 Apr 28 13:38 e83cb973-cc7b-4f03-94ce-8c4f21a9b683
drwxr-xr-x. 2 root root 4096 Apr 28 13:29 ef31097e-c317-4d58-b539-fcf82493e2d7



2016-04-28 13:37:59,313 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (org.ovirt.thread.pool-8-thread-7) [16d26c3f] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{runAsync='true', storagePoolId='7de10d80-b113-4f60-8f7f-e70f6476432b', ignoreFailoverLimit='false', storageDomainId='3843ad2f-447d-4911-bbc4-20a0ca0fb96f', imageGroupId='e83cb973-cc7b-4f03-94ce-8c4f21a9b683', imageId='716605d9-8cd6-4b57-8bd7-d7f0908714d6', dstImageGroupId='e83cb973-cc7b-4f03-94ce-8c4f21a9b683', vmId='00000000-0000-0000-0000-000000000000', dstImageId='716605d9-8cd6-4b57-8bd7-d7f0908714d6', imageDescription='', dstStorageDomainId='fb97cea4-5bf2-48fa-9ceb-b8b2e109acd4', copyVolumeType='SharedVol', volumeFormat='RAW', preallocate='Sparse', postZero='false', force='false'}), log id: 6ad0d97e



jsonrpc.Executor/3::INFO::2016-04-28 13:37:59,324::logUtils::49::dispatcher::(wrapper) Run and protect: copyImage(sdUUID=u'3843ad2f-447d-4911-bbc4-20a0ca0fb96f', spUUID=u'7de10d80-b113-4f60-8f7f-e70f6476432b', vmUUID='', srcImgUUID=u'e83cb973-cc7b-4f03-94ce-8c4f21a9b683', srcVolUUID=u'716605d9-8cd6-4b57-8bd7-d7f0908714d6', dstImgUUID=u'e83cb973-cc7b-4f03-94ce-8c4f21a9b683', dstVolUUID=u'716605d9-8cd6-4b57-8bd7-d7f0908714d6', description=u'', dstSdUUID=u'fb97cea4-5bf2-48fa-9ceb-b8b2e109acd4', volType=6, volFormat=5, preallocate=2, postZero=u'false', force=u'false')



2016-04-28 13:38:30,043 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand] (org.ovirt.thread.pool-8-thread-16) [16d26c3f] Ending command 'org.ovirt.engine.core.bl
l.storage.disk.image.CopyImageGroupCommand' successfully.



Used:
ovirt-engine-4.0.0-0.0.master.20160406161747.gita4ecba2.el7.centos.noarch
vdsm-4.17.999-724.gitb8cb30a.el7.centos.noarch

Don't see what the needinfo on me is for, clearing.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHEA-2016-1671.html

*** Bug 1367721 has been marked as a duplicate of this bug. ***