kvm: do not let a failed flush or a failed snapshot removal report success

Closing an RBD image is where librbd flushes, so a close that fails on an image
just written is the last chance a lost write has to surface. Routing those two
closes through the non-throwing helper turned that into a warning and returned
the disk anyway, which would register a volume whose tail writes never landed.
Close the written destination explicitly and let it fail the copy; the finally
still covers the paths that did not get that far.

deleteSnapshot had the same shape: a failed snapUnprotect or snapRemove was
logged and the method still answered "removed successfully", dropping the record
while the snapshot kept pinning space on the cluster, and one left protected also
blocks removal of its parent volume. It now fails, except for ENOENT, where the
snapshot is already gone and the delete has nothing left to do. The same ENOENT
tolerance keeps the RBD branch of ManageSnapshotCommand idempotent for deletes.

Also corrects the applyTimeouts javadoc, which said 0 means waiting forever for
all three options; that is true of the two operation timeouts but the connect
timeout falls back to the librados default of 300s. The snapshot test now pins
the unwind order, since destroying an IO context after its cluster handle has
been shut down would be a use after free.

Signed-off-by: Brad House <bhouse@nexthop.ai>

Author: bhouse-nexthop

agent/src/main/java/com/cloud/agent/properties/AgentProperties.java

@@ -942,7 +942,6 @@ public Property<Integer> getWorkers() {
      */
     public static final Property<Integer> RADOS_CLIENT_MOUNT_TIMEOUT = new Property<>("rados.client.mount.timeout", 30);
 
-
     public static class Property <T>{
         private String name;
         private T defaultValue;

plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtManageSnapshotCommandWrapper.java

@@ -31,6 +31,7 @@
 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.agent.api.Answer;
 import com.cloud.agent.api.ManageSnapshotAnswer;
@@ -49,6 +50,8 @@
 @ResourceWrapper(handles =  ManageSnapshotCommand.class)
 public final class LibvirtManageSnapshotCommandWrapper extends CommandWrapper<ManageSnapshotCommand, Answer, LibvirtComputingResource> {
 
+    /** librados reports a missing object as -ENOENT. */
+    private static final int RBD_ENOENT = -2;
 
     @Override
     public Answer execute(final ManageSnapshotCommand command, final LibvirtComputingResource libvirtComputingResource) {
@@ -132,11 +135,22 @@ public Answer execute(final ManageSnapshotCommand command, final LibvirtComputin
                             logger.debug("Attempting to remove RBD snapshot " + disk.getName() + "@" + snapshotName);
                             image.snapRemove(snapshotName);
                         }
+                    } catch (final RbdException e) {
+                        if (ManageSnapshotCommand.DESTROY_SNAPSHOT.equalsIgnoreCase(command.getCommandSwitch()) && e.getReturnValue() == RBD_ENOENT) {
+                            /*
+                             * Already gone. A delete whose end state is "the snapshot is not there" has
+                             * succeeded, and failing here would break a retried delete.
+                             */
+                            logger.info("RBD snapshot " + disk.getName() + "@" + snapshotName + " was already gone.");
+                        } else {
+                            /*
+                             * Reporting success here would record a snapshot in CloudStack that does not
+                             * exist on the cluster, or drop one that is still there.
+                             */
+                            logger.error("A RBD snapshot operation on " + disk.getName() + " failed. The error was: " + e.getMessage(), e);
+                            return new ManageSnapshotAnswer(command, false, "Failed to manage snapshot: " + e.toString());
+                        }
                     } catch (final Exception e) {
-                        /*
-                         * Reporting success here would record a snapshot in CloudStack that does not exist
-                         * on the cluster.
-                         */
                         logger.error("A RBD snapshot operation on " + disk.getName() + " failed. The error was: " + e.getMessage(), e);
                         return new ManageSnapshotAnswer(command, false, "Failed to manage snapshot: " + e.toString());
                     } finally {

plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtRevertSnapshotCommandWrapper.java

@@ -62,7 +62,6 @@
 @ResourceWrapper(handles = RevertSnapshotCommand.class)
 public class LibvirtRevertSnapshotCommandWrapper extends CommandWrapper<RevertSnapshotCommand, Answer, LibvirtComputingResource> {
 
-
     protected Set<StoragePoolType> storagePoolTypesThatSupportRevertSnapshot = new HashSet<>(Arrays.asList(StoragePoolType.RBD, StoragePoolType.Filesystem,
             StoragePoolType.NetworkFilesystem, StoragePoolType.SharedMountPoint));
 

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

@@ -45,7 +45,7 @@
  */
 public final class CephUtil {
 
-    protected static Logger logger = LogManager.getLogger(CephUtil.class);
+    private static final Logger logger = LogManager.getLogger(CephUtil.class);
 
     private static final String CLIENT_MOUNT_TIMEOUT = "client_mount_timeout";
     private static final String RADOS_OSD_OP_TIMEOUT = "rados_osd_op_timeout";
@@ -106,7 +106,8 @@ public static Rados connect(String authUserName, String monHost, int monPort, St
 
     /**
      * Applies the connect and operation timeouts from the agent properties. A timeout configured as 0 is
-     * left unset, which keeps the librados default of waiting forever.
+     * left unset, so librados uses its own default: waiting forever for the two operation timeouts, and
+     * 300 seconds for the connect timeout.
      */
     private static void applyTimeouts(Rados r) throws RadosException {
         int mountTimeout = AgentPropertiesFileHandler.getPropertyValue(AgentProperties.RADOS_CLIENT_MOUNT_TIMEOUT);

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

@@ -172,6 +172,9 @@ public class KVMStorageProcessor implements StorageProcessor {
     private String _manageSnapshotPath;
     private int _cmdsTimeout;
 
+    /** librados reports a missing object as -ENOENT. */
+    private static final int RBD_ENOENT = -2;
+
     private static final String MANAGE_SNAPSTHOT_CREATE_OPTION = "-c";
     private static final String NAME_OPTION = "-n";
     /**
@@ -2948,8 +2951,22 @@ public Answer deleteSnapshot(final DeleteCommand cmd) {
                         logger.info("Snapshot " + snapshotFullName + " successfully removed from " +
                                 primaryPool.getType().toString() + "  pool.");
                     } catch (RbdException e) {
-                        logger.error("Failed to remove snapshot " + snapshotFullName + ", with exception: " + e.toString() +
-                            ", RBD error: " + ErrorCode.getErrorMessage(e.getReturnValue()));
+                        if (e.getReturnValue() == RBD_ENOENT) {
+                            /*
+                             * Already gone. A delete whose end state is "the snapshot is not there" has
+                             * succeeded, and failing here would break a retried delete.
+                             */
+                            logger.info("RBD snapshot " + snapshotFullName + " was already gone.");
+                        } else {
+                            /*
+                             * Anything else means the snapshot is still on the cluster. Reporting success
+                             * would drop the record while it keeps pinning space, and one left protected
+                             * also blocks removal of its parent volume.
+                             */
+                            logger.error("Failed to remove snapshot " + snapshotFullName + ", with exception: " + e.toString() +
+                                ", RBD error: " + ErrorCode.getErrorMessage(e.getReturnValue()));
+                            throw e;
+                        }
                     }
                 } finally {
                     closeRbdImage(rbd, image, disk.getName());

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

@@ -1420,6 +1420,14 @@ private KVMPhysicalDisk createDiskFromTemplateOnRBD(KVMPhysicalDisk template,
                                 rbd.copy(srcImage, destImage);
 
                                 logger.debug("Finished copying " + srcImage.getName() +  " to " + destImage.getName() + " in Ceph pool " + srcPool.getSourceDir());
+
+                                /*
+                                 * rbd_close is where librbd flushes, so closing an image that was just
+                                 * written is the last point a lost write can surface. It has to fail the
+                                 * copy rather than be logged and forgotten.
+                                 */
+                                rbd.close(destImage);
+                                destImage = null;
                             } finally {
                                 CephUtil.closeQuietly(rbd, destImage, disk.getName());
                             }
@@ -1517,6 +1525,13 @@ private KVMPhysicalDisk createDiskFromTemplateOnRBD(KVMPhysicalDisk template,
                         logger.debug("Copying " + template.getName() + " from Ceph cluster " + rSrc.confGet("mon_host") + " to " + disk.getName()
                                 + " on cluster " + rDest.confGet("mon_host"));
                         sRbd.copy(srcImage, destImage);
+
+                        /*
+                         * rbd_close is where librbd flushes, so closing the destination is the last point
+                         * a lost write can surface. It has to fail the copy rather than be logged.
+                         */
+                        dRbd.close(destImage);
+                        destImage = null;
                     } finally {
                         CephUtil.closeQuietly(sRbd, srcImage, template.getName());
                         CephUtil.closeQuietly(dRbd, destImage, disk.getName());

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

@@ -50,6 +50,7 @@
 import org.mockito.Mock;
 import org.mockito.MockedConstruction;
 import org.mockito.MockedStatic;
+import org.mockito.InOrder;
 import org.mockito.Mockito;
 import org.mockito.MockitoAnnotations;
 import org.mockito.Spy;
@@ -549,9 +550,15 @@ public void takeRbdVolumeSnapshotOfStoppedVmTestCreatesSnapshotExactlyOnce() thr
 
             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);
-            Mockito.verify(radosMock).shutDown();
+
+            /*
+             * Order matters: Rados.shutDown() releases the native cluster handle, so destroying the IO
+             * context after it would be a use after free.
+             */
+            InOrder unwind = Mockito.inOrder(rbd.constructed().get(0), radosMock);
+            unwind.verify(rbd.constructed().get(0)).close(rbdImageMock);
+            unwind.verify(radosMock).ioCtxDestroy(ioCtxMock);
+            unwind.verify(radosMock).shutDown();
         }
     }