[preview] kvm: fix RBD exclusive-lock leak that breaks revertSnapshot on Ceph

plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/storage/KVMStorageProcessor.java

@@ -2339,33 +2339,36 @@ private CreateObjectAnswer takeClvmVolumeSnapshotOfStoppedVm(KVMPhysicalDisk dis
      * barriers properly (>2.6.32) this won't be any different then pulling the power
      * cord out of a running machine.
      */
-    private Long takeRbdVolumeSnapshotOfStoppedVm(KVMStoragePool primaryPool, KVMPhysicalDisk disk, String snapshotName) {
+    protected Long takeRbdVolumeSnapshotOfStoppedVm(KVMStoragePool primaryPool, KVMPhysicalDisk disk, String snapshotName) {
         Long snapshotSize = null;
+        Rados r = null;
+        IoCTX io = null;
+        Rbd rbd = null;
+        RbdImage image = null;
         try {
-            Rados r = radosConnect(primaryPool);
+            r = radosConnect(primaryPool);
 
-            final IoCTX io = r.ioCtxCreate(primaryPool.getSourceDir());
-            final Rbd rbd = new Rbd(io);
-            final RbdImage image = rbd.open(disk.getName());
+            io = r.ioCtxCreate(primaryPool.getSourceDir());
+            rbd = new Rbd(io);
+            image = rbd.open(disk.getName());
 
             logger.debug("Attempting to create RBD snapshot {}@{}", disk.getName(), snapshotName);
             image.snapCreate(snapshotName);
 
-            image.snapCreate(snapshotName);
             long rbdSnapshotSize = getRbdSnapshotSize(primaryPool.getSourceDir(), disk.getName(), snapshotName, primaryPool.getSourceHost(), primaryPool.getAuthUserName(), primaryPool.getAuthSecret());
             if (rbdSnapshotSize > 0) {
                 snapshotSize = rbdSnapshotSize;
             }
-
-            rbd.close(image);
-            r.ioCtxDestroy(io);
         } catch (final Exception e) {
             logger.error("A RBD snapshot operation on [{}] failed. The error was: {}", disk.getName(), e.getMessage(), e);
+        } finally {
+            closeRbdImage(rbd, image, disk.getName());
+            destroyRadosIoCtx(r, io, disk.getName());
         }
         return snapshotSize;
     }
 
-    private long getRbdSnapshotSize(String poolPath, String diskName, String snapshotName, String rbdMonitor, String authUser, String authSecret) {
+    protected long getRbdSnapshotSize(String poolPath, String diskName, String snapshotName, String rbdMonitor, String authUser, String authSecret) {
         logger.debug("Get RBD snapshot size for {}/{}@{}", poolPath, diskName, snapshotName);
         //cmd: rbd du <pool>/<disk-name>@<snapshot-name> --format json --mon-host <monitor-host> --id <user> --key <key> 2>/dev/null
         String snapshotDetailsInJson = Script.runSimpleBashScript(String.format("rbd du %s/%s@%s --format json --mon-host %s --id %s --key %s 2>/dev/null", poolPath, diskName, snapshotName, rbdMonitor, authUser, authSecret));
@@ -2652,7 +2655,7 @@ protected boolean isAvailablePoolSizeDividedByDiskSizeLesserThanMinRate(long ava
         return ((availablePoolSize * 1d) / (diskSize * 1d)) < MIN_RATE_BETWEEN_AVAILABLE_POOL_AND_DISK_SIZE_TO_TAKE_DISK_SNAPSHOT;
     }
 
-    private Rados radosConnect(final KVMStoragePool primaryPool) throws RadosException {
+    protected Rados radosConnect(final KVMStoragePool primaryPool) throws RadosException {
         Rados r = new Rados(primaryPool.getAuthUserName());
         r.confSet(CEPH_MON_HOST, primaryPool.getSourceHost() + ":" + primaryPool.getSourcePort());
         r.confSet(CEPH_AUTH_KEY, primaryPool.getAuthSecret());
@@ -2662,6 +2665,50 @@ private Rados radosConnect(final KVMStoragePool primaryPool) throws RadosExcepti
         return r;
     }
 
+    /**
+     * Closes an RBD image if it was opened; never throws. An image left open keeps this client's RBD
+     * exclusive-lock, which later makes 'rbd snap rollback' (revertSnapshot) fail with EROFS and keeps
+     * the image busy so it cannot be removed.
+     */
+    protected void closeRbdImage(Rbd rbd, RbdImage image, String imageName) {
+        if (image == null) {
+            return;
+        }
+        try {
+            rbd.close(image);
+        } catch (final Exception e) {
+            logger.warn("Failed to close RBD image [{}]. The error was: {}", imageName, e.getMessage(), e);
+        }
+    }
+
+    /** Destroys a RADOS IO context if it was created; never throws. */
+    protected void destroyRadosIoCtx(Rados r, IoCTX io, String contextDescription) {
+        if (io == null) {
+            return;
+        }
+        try {
+            r.ioCtxDestroy(io);
+        } catch (final Exception e) {
+            logger.warn("Failed to destroy the RADOS IO context used for [{}]. The error was: {}", contextDescription, e.getMessage(), e);
+        }
+    }
+
+    /**
+     * Unprotects an RBD snapshot if it was protected; never throws. A snapshot left protected cannot
+     * be deleted, and neither can its volume.
+     */
+    protected void unprotectRbdSnapshot(RbdImage image, String snapshotName, boolean snapProtected) {
+        if (!snapProtected) {
+            return;
+        }
+        try {
+            image.snapUnprotect(snapshotName);
+        } catch (final Exception e) {
+            logger.error("Failed to unprotect RBD snapshot [{}]; it and its volume cannot be deleted until this is resolved manually. The error was: {}",
+                    snapshotName, e.getMessage(), e);
+        }
+    }
+
     @Override
     public Answer deleteVolume(final DeleteCommand cmd) {
         final VolumeObjectTO vol = (VolumeObjectTO)cmd.getData();
@@ -2811,17 +2858,24 @@ private KVMPhysicalDisk createRBDvolumeFromRBDSnapshot(KVMPhysicalDisk volume, S
         disk.setSize(size > volume.getVirtualSize() ? size : volume.getVirtualSize());
         disk.setVirtualSize(size > volume.getVirtualSize() ? size : disk.getSize());
 
+        Rados r = null;
+        IoCTX io = null;
+        Rbd rbd = null;
+        RbdImage srcImage = null;
+        RbdImage diskImage = null;
+        boolean snapProtected = false;
+
         try {
 
-            Rados r = new Rados(srcPool.getAuthUserName());
+            r = new Rados(srcPool.getAuthUserName());
             r.confSet("mon_host", srcPool.getSourceHost() + ":" + srcPool.getSourcePort());
             r.confSet("key", srcPool.getAuthSecret());
             r.confSet("client_mount_timeout", "30");
             r.connect();
 
-            IoCTX io = r.ioCtxCreate(srcPool.getSourceDir());
-            Rbd rbd = new Rbd(io);
-            RbdImage srcImage = rbd.open(volume.getName());
+            io = r.ioCtxCreate(srcPool.getSourceDir());
+            rbd = new Rbd(io);
+            srcImage = rbd.open(volume.getName());
 
             List<RbdSnapInfo> snaps = srcImage.snapList();
             boolean snapFound = false;
@@ -2837,23 +2891,26 @@ private KVMPhysicalDisk createRBDvolumeFromRBDSnapshot(KVMPhysicalDisk volume, S
                 return null;
             }
             srcImage.snapProtect(snapshotName);
+            snapProtected = true;
 
             logger.debug(String.format("Try to clone snapshot %s on RBD", snapshotName));
             rbd.clone(volume.getName(), snapshotName, io, disk.getName(), LibvirtStorageAdaptor.RBD_FEATURES, 0);
-            RbdImage diskImage = rbd.open(disk.getName());
+            diskImage = rbd.open(disk.getName());
             if (disk.getVirtualSize() > volume.getVirtualSize()) {
                 diskImage.resize(disk.getVirtualSize());
             }
 
             diskImage.flatten();
-            rbd.close(diskImage);
-
-            srcImage.snapUnprotect(snapshotName);
-            rbd.close(srcImage);
-            r.ioCtxDestroy(io);
         } catch (RadosException | RbdException e) {
             logger.error(String.format("Failed due to %s", e.getMessage()), e);
             disk = null;
+        } finally {
+            // Every handle has to be released on all paths, including the "snapshot not found" return and
+            // any failure of clone/resize/flatten.
+            closeRbdImage(rbd, diskImage, newUuid);
+            unprotectRbdSnapshot(srcImage, snapshotName, snapProtected);
+            closeRbdImage(rbd, srcImage, volume.getName());
+            destroyRadosIoCtx(r, io, snapshotName);
         }
 
         return disk;

plugins/hypervisors/kvm/src/test/java/com/cloud/hypervisor/kvm/storage/KVMStorageProcessorTest.java

@@ -18,6 +18,11 @@
  */
 package com.cloud.hypervisor.kvm.storage;
 
+import com.ceph.rados.IoCTX;
+import com.ceph.rados.Rados;
+import com.ceph.rbd.Rbd;
+import com.ceph.rbd.RbdException;
+import com.ceph.rbd.RbdImage;
 import com.cloud.exception.InternalErrorException;
 import com.cloud.hypervisor.kvm.resource.LibvirtComputingResource;
 import com.cloud.hypervisor.kvm.resource.LibvirtDomainXMLParser;
@@ -108,6 +113,11 @@ public class KVMStorageProcessorTest {
     private static final String directDownloadTemporaryPath = "/var/lib/libvirt/images/dd";
     private static final long templateSize = 80000L;
 
+    private static final String RBD_POOL_NAME = "cloudstack";
+    private static final String RBD_IMAGE_NAME = "b7a1f0a9-0f0e-4a1a-9a35-1c1a2e0f1b5e";
+    private static final String SNAPSHOT_NAME = "8f1c1f0b-9d3e-4c2a-8a3d-6f0b2c9e1d47";
+    private static final long SNAPSHOT_SIZE = 196624L;
+
     private AutoCloseable closeable;
 
     @Before
@@ -499,4 +509,71 @@ public void getDiskLabelToSnapshotTestDiskMatches() throws LibvirtException {
 
         Assert.assertEquals("vda", result);
     }
+
+    /**
+     * Wires a mocked Ceph stack for {@link KVMStorageProcessor#takeRbdVolumeSnapshotOfStoppedVm} and returns the
+     * mocked disk. The Rbd instance is created inside the method under test, so it is mocked by construction.
+     */
+    private KVMPhysicalDisk prepareRbdSnapshotMocks(Rados radosMock, IoCTX ioCtxMock) throws Exception {
+        KVMPhysicalDisk diskMock = Mockito.mock(KVMPhysicalDisk.class);
+        Mockito.lenient().doReturn(RBD_IMAGE_NAME).when(diskMock).getName();
+
+        Mockito.lenient().doReturn(RBD_POOL_NAME).when(kvmStoragePoolMock).getSourceDir();
+        Mockito.lenient().doReturn("10.0.0.1").when(kvmStoragePoolMock).getSourceHost();
+        Mockito.lenient().doReturn("cloudstack").when(kvmStoragePoolMock).getAuthUserName();
+        Mockito.lenient().doReturn("secret").when(kvmStoragePoolMock).getAuthSecret();
+
+        Mockito.doReturn(radosMock).when(storageProcessorSpy).radosConnect(kvmStoragePoolMock);
+        Mockito.doReturn(ioCtxMock).when(radosMock).ioCtxCreate(RBD_POOL_NAME);
+        Mockito.lenient().doReturn(SNAPSHOT_SIZE).when(storageProcessorSpy).getRbdSnapshotSize(Mockito.anyString(), Mockito.anyString(),
+                Mockito.anyString(), Mockito.anyString(), Mockito.anyString(), Mockito.anyString());
+
+        return diskMock;
+    }
+
+    /**
+     * A duplicated snapCreate call used to throw "snapshot already exists" on every single RBD snapshot, which then
+     * skipped the cleanup below and leaked the image's exclusive-lock.
+     */
+    @Test
+    public void takeRbdVolumeSnapshotOfStoppedVmTestCreatesSnapshotExactlyOnce() throws Exception {
+        Rados radosMock = Mockito.mock(Rados.class);
+        IoCTX ioCtxMock = Mockito.mock(IoCTX.class);
+        RbdImage rbdImageMock = Mockito.mock(RbdImage.class);
+        KVMPhysicalDisk diskMock = prepareRbdSnapshotMocks(radosMock, ioCtxMock);
+
+        try (MockedConstruction<Rbd> rbd = Mockito.mockConstruction(Rbd.class, ((mock, context) ->
+                Mockito.doReturn(rbdImageMock).when(mock).open(RBD_IMAGE_NAME)))) {
+
+            Long result = storageProcessorSpy.takeRbdVolumeSnapshotOfStoppedVm(kvmStoragePoolMock, diskMock, SNAPSHOT_NAME);
+
+            Assert.assertEquals(Long.valueOf(SNAPSHOT_SIZE), result);
+            Mockito.verify(rbdImageMock, Mockito.times(1)).snapCreate(SNAPSHOT_NAME);
+            Mockito.verify(rbd.constructed().get(0)).close(rbdImageMock);
+            Mockito.verify(radosMock).ioCtxDestroy(ioCtxMock);
+        }
+    }
+
+    /**
+     * While the image stays open this client holds the RBD exclusive-lock, and a later 'rbd snap rollback'
+     * (revertSnapshot) from another host fails with EROFS. The handles must be released even when the snapshot fails.
+     */
+    @Test
+    public void takeRbdVolumeSnapshotOfStoppedVmTestReleasesHandlesWhenSnapshotFails() throws Exception {
+        Rados radosMock = Mockito.mock(Rados.class);
+        IoCTX ioCtxMock = Mockito.mock(IoCTX.class);
+        RbdImage rbdImageMock = Mockito.mock(RbdImage.class);
+        KVMPhysicalDisk diskMock = prepareRbdSnapshotMocks(radosMock, ioCtxMock);
+        Mockito.doThrow(new RbdException("Failed to create snapshot")).when(rbdImageMock).snapCreate(SNAPSHOT_NAME);
+
+        try (MockedConstruction<Rbd> rbd = Mockito.mockConstruction(Rbd.class, ((mock, context) ->
+                Mockito.doReturn(rbdImageMock).when(mock).open(RBD_IMAGE_NAME)))) {
+
+            Long result = storageProcessorSpy.takeRbdVolumeSnapshotOfStoppedVm(kvmStoragePoolMock, diskMock, SNAPSHOT_NAME);
+
+            Assert.assertNull(result);
+            Mockito.verify(rbd.constructed().get(0)).close(rbdImageMock);
+            Mockito.verify(radosMock).ioCtxDestroy(ioCtxMock);
+        }
+    }
 }

server/src/main/java/com/cloud/storage/StorageManagerImpl.java

@@ -3492,7 +3492,13 @@ protected boolean storagePoolHasEnoughIops(long requestedIops, List<Pair<Volume,
         long futureIops = currentIops + requestedIops;
         boolean hasEnoughIops = futureIops <= pool.getCapacityIops();
         String hasCapacity = hasEnoughIops ? "has" : "does not have";
-        logger.debug(String.format("Pool [%s] %s enough IOPS to allocate volumes [%s].", pool, hasCapacity, requestedVolumes));
+        StringBuilder stringBuilder = new StringBuilder();
+        stringBuilder.append(String.format("Pool [%s] %s enough IOPS to allocate volumes [%s]", pool, hasCapacity, requestedVolumes));
+        if (!hasEnoughIops) {
+            stringBuilder.append(String.format(" - Insufficient un-allocated IOPS for storage allocation: " +
+                    "capacityIops : %d, usedIops : %d, requestedIops : %d", pool.getCapacityIops(), currentIops, requestedIops));
+        }
+        logger.debug(stringBuilder.toString());
         return hasEnoughIops;
     }