Bug 1292092 - Bogus log when unlink operation fails during deleteImage on file storage.
Bogus log when unlink operation fails during deleteImage on file storage.
Product: vdsm
Classification: oVirt
Component: General (Show other bugs)
Unspecified Unspecified
unspecified Severity medium (vote)
: ovirt-3.6.2
: 4.17.16
Assigned To: Idan Shaby
Depends On:
  Show dependency treegraph
Reported: 2015-12-16 07:57 EST by Nir Soffer
Modified: 2016-02-18 06:05 EST (History)
7 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 1291207
Last Closed: 2016-02-18 06:05:11 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rule-engine: ovirt‑3.6.z+
ylavi: planning_ack+
amureini: devel_ack+
rule-engine: testing_ack+

Attachments (Terms of Use)

External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 50589 master MERGED fileSD: Do not try to remove non-existent lease file 2015-12-17 14:08 EST
oVirt gerrit 50804 master MERGED fileSD: improve error handling in deleteImage 2015-12-24 02:10 EST
oVirt gerrit 51229 ovirt-3.6 MERGED fileSD: improve error handling in deleteImage 2016-01-03 15:01 EST
oVirt gerrit 51299 ovirt-3.6 MERGED fileSD: improve error handling in deleteImage 2016-01-05 04:52 EST

  None (edit)
Description Nir Soffer 2015-12-16 07:57:54 EST
+++ This bug was initially created as a clone of Bug #1291207 +++

Description of problem:

When .meta or .lease file unlink fail, we log that the volume file could
not be removed instead of logging about the failure to remove the actual
file, making debugging harder.

Version-Release number of selected component (if applicable):

How reproducible:

Steps to Reproduce:
1. Export a VM with disk to export domain
2. Remove the VM from export domain

Actual results:
Trying to remove the non-existent .lease file, we log about the volume file:

jsonrpc.Executor/1::ERROR::2015-12-14 10:44:56,320::fileSD::409::Storage.StorageDomain::(deleteImage) vol: /rhev/data-center/mnt/
move_me_e5b31639-bf4d-475d-b286-fbd09ae835c0/6f3b44a7-60f4-4c5a-8e33-5c0bd592d04d can't be removed.
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/fileSD.py", line 406, in deleteImage
  File "/usr/share/vdsm/storage/outOfProcess.py", line 246, in remove
  File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 491, in unlink
    return self._sendCommand("unlink", {"path": path}, self.timeout)
  File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 427, in _sendCommand
    raise OSError(errcode, errstr)
OSError: [Errno 2] No such file or directory

The failed operation was:


But the logged message is:

  vol: /rhev/data-center/mnt/
move_me_e5b31639-bf4d-475d-b286-fbd09ae835c0/6f3b44a7-60f4-4c5a-8e33-5c0bd592d04d can't be removed.

This is a lie, as the file "6f3b44a7-60f4-4c5a-8e33-5c0bd592d04d" was removed just before
trying to remove the file "6f3b44a7-60f4-4c5a-8e33-5c0bd592d04d.lease".

Expected result:

Log the error with the actual path that failed.
The issue of deleting non-existent lease file is handled in bug 1291207
this bug is about logging correctly.
Comment 1 Nir Soffer 2015-12-16 07:59:34 EST
Setting to medium because bogus logs make it harder to debug real issues.
Comment 2 Nir Soffer 2015-12-16 08:16:59 EST
The unlink operation failed with ENOENT. This means that the delete operation was
not needed, as the file does not exist.

In this case we should log a debug message, since we do not expect a missing
volume file in an image directory (maybe we do when removing garbage volumes),
and continue the operation.

And there is even worse problem, that can fail the entire operation if deleting
the vol-uuid file or vol-uuid.meta file failed.

In this flow, we are removing these files:


We have one error handler for the 3 unlink calls, so if removing vol-uuid 
fails, we will not try to remove vol-uuid.meta and vol-uuid.lease, and
deleting the image directory will fail because rmdir works only for
empty directories.

The fix should log errors (or debug message for ENOENT) for each unlink
operation, so we always delete all the vol-uuid* files.
Comment 3 Elad 2016-01-18 05:20:24 EST
Tested the following over file data and export domain:
1) Manually removed the volume file from /rhev/data-center/pool/sd/images/image/
2) Removed the disk from the domain

For both export and data domains, the delete operation all the image content proceeded and the images got removed successfully.

jsonrpc.Executor/6::DEBUG::2016-01-18 12:13:16,512::fileSD::410::Storage.StorageDomain::(_deleteVolumeFile) Removing file: /rhev/data-center/mnt/
jsonrpc.Executor/6::WARNING::2016-01-18 12:13:16,514::fileSD::415::Storage.StorageDomain::(_deleteVolumeFile) File u'/rhev/data-center/mnt/
images/_remove_me_833762ef-2597-44f8-a8f5-41ad5276698b/b9a13fe9-296a-4685-8038-f5299f0a650e' does not exist: [Errno 2] No such file or directory
jsonrpc.Executor/6::DEBUG::2016-01-18 12:13:16,514::fileSD::410::Storage.StorageDomain::(_deleteVolumeFile) Removing file: /rhev/data-center/mnt/
jsonrpc.Executor/6::DEBUG::2016-01-18 12:13:16,516::fileSD::410::Storage.StorageDomain::(_deleteVolumeFile) Removing file: /rhev/data-center/mnt/
jsonrpc.Executor/6::DEBUG::2016-01-18 12:13:16,517::fileSD::402::Storage.StorageDomain::(deleteImage) Removing directory: /rhev/data-center/mnt/

Verified using:

Note You need to log in before you can comment on or make changes to this bug.