diff --git a/nova/tests/unit/virt/libvirt/test_imagebackend.py b/nova/tests/unit/virt/libvirt/test_imagebackend.py index 7e21b06d284c..8cba305fe816 100644 --- a/nova/tests/unit/virt/libvirt/test_imagebackend.py +++ b/nova/tests/unit/virt/libvirt/test_imagebackend.py @@ -14,6 +14,7 @@ # under the License. import base64 +import errno import os import shutil import tempfile @@ -1832,3 +1833,44 @@ class BackendTestCase(test.NoDBTestCase): def test_image_default(self): self._test_image('default', imagebackend.Flat, imagebackend.Qcow2) + + +class UtimeWorkaroundTestCase(test.NoDBTestCase): + ERROR_STUB = "sentinel.path: [Errno 13] Permission Denied" + + def setUp(self): + super(UtimeWorkaroundTestCase, self).setUp() + self.mock_utime = self.useFixture( + fixtures.MockPatch('nova.privsep.path.utime')).mock + + def test_update_utime_no_error(self): + # If utime doesn't raise an error we shouldn't raise or log anything + imagebackend._update_utime_ignore_eacces(mock.sentinel.path) + self.mock_utime.assert_called_once_with(mock.sentinel.path) + self.assertNotIn(self.ERROR_STUB, self.stdlog.logger.output) + + def test_update_utime_eacces(self): + # If utime raises EACCES we should log the error, but ignore it + e = OSError() + e.errno = errno.EACCES + e.strerror = "Permission Denied" + self.mock_utime.side_effect = e + + imagebackend._update_utime_ignore_eacces(mock.sentinel.path) + self.mock_utime.assert_called_once_with(mock.sentinel.path) + self.assertIn(self.ERROR_STUB, self.stdlog.logger.output) + + def test_update_utime_eio(self): + # If utime raises any other error we should raise it + e = OSError() + e.errno = errno.EIO + e.strerror = "IO Error" + self.mock_utime.side_effect = e + + ex = self.assertRaises( + OSError, imagebackend._update_utime_ignore_eacces, + mock.sentinel.path) + self.assertIs(ex, e) + + self.mock_utime.assert_called_once_with(mock.sentinel.path) + self.assertNotIn(self.ERROR_STUB, self.stdlog.logger.output) diff --git a/nova/virt/libvirt/imagebackend.py b/nova/virt/libvirt/imagebackend.py index fcdedac74de9..7a966f77fef7 100644 --- a/nova/virt/libvirt/imagebackend.py +++ b/nova/virt/libvirt/imagebackend.py @@ -16,6 +16,7 @@ import abc import base64 import contextlib +import errno import functools import os import shutil @@ -52,6 +53,31 @@ LOG = logging.getLogger(__name__) IMAGE_API = image.API() +# NOTE(neiljerram): Don't worry if this fails. This sometimes happens, with +# EACCES (Permission Denied), when the base file is on an NFS client +# filesystem. I don't understand why, but wonder if it's a similar problem as +# the one that motivated using touch instead of utime in ec9d5e375e2. In any +# case, IIUC, timing isn't the primary thing that the image cache manager uses +# to determine when the base file is in use. The primary mechanism for that is +# whether there is a matching disk file for a current instance. The timestamp +# on the base file is only used when deciding whether to delete a base file +# that is _not_ in use; so it is not a big deal if that deletion happens +# slightly earlier, for an unused base file, because of one of these preceding +# utime calls having failed. +# NOTE(mdbooth): Only use this method for updating the utime of an image cache +# entry during disk creation. +# TODO(mdbooth): Remove or rework this when we understand the problem. +def _update_utime_ignore_eacces(path): + try: + nova.privsep.path.utime(path) + except OSError as e: + with excutils.save_and_reraise_exception(logger=LOG) as ctxt: + if e.errno == errno.EACCES: + LOG.warning("Ignoring failure to update utime of %(path)s: " + "%(error)s", {'path': path, 'error': e}) + ctxt.reraise = False + + @six.add_metaclass(abc.ABCMeta) class Image(object): @@ -543,7 +569,7 @@ class Flat(Image): # NOTE(mikal): Update the mtime of the base file so the image # cache manager knows it is in use. - nova.privsep.path.utime(base) + _update_utime_ignore_eacces(base) self.verify_base_size(base, size) if not os.path.exists(self.path): with fileutils.remove_path_on_error(self.path): @@ -599,7 +625,7 @@ class Qcow2(Image): # NOTE(ankit): Update the mtime of the base file so the image # cache manager knows it is in use. - nova.privsep.path.utime(base) + _update_utime_ignore_eacces(base) self.verify_base_size(base, size) legacy_backing_size = None @@ -1094,7 +1120,7 @@ class Ploop(Image): prepare_template(target=base, *args, **kwargs) else: # Disk already exists in cache, just update time - nova.privsep.path.utime(base) + _update_utime_ignore_eacces(base) self.verify_base_size(base, size) if os.path.exists(self.path):