diff --git a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasBackupHelper.java b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasBackupHelper.java index 5bfa880feb05..a419e0a66004 100644 --- a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasBackupHelper.java +++ b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasBackupHelper.java @@ -217,6 +217,7 @@ private Pair executeStoppedVmBackup(AblestackNasTakeBackupComma Path dest = null; String dummyVmName = String.format("DUMMY-VM-%s", command.getCheckpointName().replace('.', '-')); Connect conn = null; + long startedAt = System.currentTimeMillis(); try { LOGGER.info("Starting stopped VM NAS backup for vm=[{}], dummyVm=[{}], backupType=[{}]", command.getVmName(), dummyVmName, command.getBackupType()); @@ -228,10 +229,16 @@ private Pair executeStoppedVmBackup(AblestackNasTakeBackupComma dest = mountPoint.resolve(command.getBackupPath()); Files.createDirectories(dest.resolve("checkpoints")); markBackupInProgress(dest, command); + logStoppedBackupTrace(command, dummyVmName, "T0_BEFORE_DUMMY_CREATE", startedAt, + "source qcow2 state before dummy VM creation"); + logSourceQcow2State(command, dummyVmName, "T0_BEFORE_DUMMY_CREATE", diskPaths, startedAt); conn = LibvirtConnection.getConnection(); String dummyVmXml = buildDummyVmXml(dummyVmName, diskPaths, conn); resource.startVM(conn, dummyVmName, dummyVmXml, Domain.CreateFlags.PAUSED); + logStoppedBackupTrace(command, dummyVmName, "T1_AFTER_DUMMY_PAUSED_CREATE", startedAt, + "dummy VM was created with PAUSED flag"); + logDummyVmRuntimeState(command, dummyVmName, "T1_AFTER_DUMMY_PAUSED_CREATE", startedAt); if (isIncremental(command) && command.getParentCheckpointPath() != null && !command.getParentCheckpointPath().isEmpty()) { redefineCheckpointIfNeeded(dummyVmName, mountPoint.resolve(command.getParentCheckpointPath())); @@ -252,10 +259,16 @@ private Pair executeStoppedVmBackup(AblestackNasTakeBackupComma LOGGER.error(failureDetails); return new Pair<>(backupBeginResult.first(), failureDetails); } + logStoppedBackupTrace(command, dummyVmName, "T2_AFTER_BACKUP_BEGIN", startedAt, + "backup-begin accepted by libvirt"); + logDummyVmRuntimeState(command, dummyVmName, "T2_AFTER_BACKUP_BEGIN", startedAt); try { final long effectiveTimeoutMillis = command.getWait() > 0 ? TimeUnit.SECONDS.toMillis(command.getWait()) : resource.getCmdsTimeout(); - waitForBackup(dummyVmName, effectiveTimeoutMillis); + waitForBackup(command, dummyVmName, effectiveTimeoutMillis, startedAt); + logStoppedBackupTrace(command, dummyVmName, "T3_AFTER_DOMJOB_COMPLETED", startedAt, + "domjobinfo reported completed backup job"); + logDummyVmRuntimeState(command, dummyVmName, "T3_AFTER_DOMJOB_COMPLETED", startedAt); } catch (IOException e) { cancelBackupJob(dummyVmName); throw e; @@ -266,11 +279,18 @@ private Pair executeStoppedVmBackup(AblestackNasTakeBackupComma } dumpCheckpointXml(dummyVmName, command.getCheckpointName(), dest); + logStoppedBackupTrace(command, dummyVmName, "CHECKPOINT_DUMPED", startedAt, + "checkpoint XML was dumped before dummy cleanup"); + logCheckpointState(command, dummyVmName, command.getCheckpointName(), startedAt); Files.deleteIfExists(backupXml); Files.deleteIfExists(checkpointXml); runCommand(String.format("sync")); + logStoppedBackupTrace(command, dummyVmName, "BACKUP_MARKER_CREATE_BEGIN", startedAt, + "creating backup complete marker before finally cleanup"); markBackupComplete(dest, command); + logStoppedBackupTrace(command, dummyVmName, "BACKUP_MARKER_CREATED", startedAt, + "backup complete marker created"); String output = listTopLevelFileSizes(dest); LOGGER.info("Completed stopped VM NAS backup for vm=[{}], dummyVm=[{}]", command.getVmName(), dummyVmName); return new Pair<>(0, output); @@ -284,7 +304,12 @@ private Pair executeStoppedVmBackup(AblestackNasTakeBackupComma mountPoint = null; return new Pair<>(1, e.getMessage()); } finally { + logStoppedBackupTrace(command, dummyVmName, "DUMMY_DESTROY_BEGIN", startedAt, + "starting dummy VM cleanup"); cleanupDummyVm(dummyVmName); + logStoppedBackupTrace(command, dummyVmName, "T4_AFTER_DUMMY_DESTROY", startedAt, + "dummy VM cleanup finished; collecting offline source qcow2 state"); + logSourceQcow2State(command, dummyVmName, "T4_AFTER_DUMMY_DESTROY", diskPaths, startedAt); unmountRepository(command, mountPoint); } } @@ -533,10 +558,12 @@ private Path writeCheckpointXml(Path dest, AblestackNasTakeBackupCommand command return checkpointXml; } - private void waitForBackup(String vmName, long timeoutMillis) throws IOException { + private void waitForBackup(AblestackNasTakeBackupCommand command, String vmName, long timeoutMillis, long startedAt) throws IOException { long remainingMillis = timeoutMillis; while (remainingMillis > 0) { String result = checkBackupJob(vmName); + LOGGER.info("[STOPPED_BACKUP_TRACE] phase=[DOMJOBINFO_POLL] vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], output=[{}]", + command.getVmName(), vmName, command.getBackupType(), command.getCheckpointName(), System.currentTimeMillis() - startedAt, result); if (result != null && result.contains("Completed") && result.contains("Backup")) { return; } @@ -586,6 +613,113 @@ private void dumpCheckpointXml(String vmName, String checkpointName, Path dest) shellQuote(vmName), shellQuote(checkpointName), shellQuote(checkpointDest.toString()))); } + private void logStoppedBackupTrace(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, long startedAt, String message) { + LOGGER.info("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], message=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), + System.currentTimeMillis() - startedAt, message); + } + + private void logDummyVmRuntimeState(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, long startedAt) { + logTraceCommandOutput(command, dummyVmName, phase, startedAt, "query-status", String.format( + "virsh -c qemu:///system qemu-monitor-command %s --pretty %s", + shellQuote(dummyVmName), shellQuote("{\"execute\":\"query-status\"}"))); + logTraceCommandOutput(command, dummyVmName, phase, startedAt, "query-block", String.format( + "virsh -c qemu:///system qemu-monitor-command %s --pretty %s", + shellQuote(dummyVmName), shellQuote("{\"execute\":\"query-block\"}"))); + logTraceCommandOutput(command, dummyVmName, phase, startedAt, "query-named-block-nodes", String.format( + "virsh -c qemu:///system qemu-monitor-command %s --pretty %s", + shellQuote(dummyVmName), shellQuote("{\"execute\":\"query-named-block-nodes\"}"))); + logTraceCommandOutput(command, dummyVmName, phase, startedAt, "domjobinfo", String.format( + "virsh -c qemu:///system domjobinfo %s --completed --keep-completed", + shellQuote(dummyVmName))); + } + + private void logCheckpointState(AblestackNasTakeBackupCommand command, String dummyVmName, String checkpointName, long startedAt) { + logTraceCommandOutput(command, dummyVmName, "CHECKPOINT_DUMPED", startedAt, "checkpoint-list", String.format( + "virsh -c qemu:///system checkpoint-list --domain %s --tree", + shellQuote(dummyVmName))); + logTraceCommandOutput(command, dummyVmName, "CHECKPOINT_DUMPED", startedAt, "checkpoint-info", String.format( + "virsh -c qemu:///system checkpoint-info --domain %s --checkpointname %s", + shellQuote(dummyVmName), shellQuote(checkpointName))); + } + + private void logSourceQcow2State(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, List diskPaths, long startedAt) { + for (int i = 0; i < diskPaths.size(); i++) { + String diskPath = diskPaths.get(i); + if (diskPath == null || diskPath.startsWith("rbd:")) { + continue; + } + logTraceDiskCommandOutput(command, dummyVmName, phase, startedAt, i, diskPath, "qemu-img-info", String.format( + "if command -v jq >/dev/null 2>&1; then qemu-img info -U --output=json %s | jq -c '{filename, virtual_size: .\"virtual-size\", actual_size: .\"actual-size\", dirty_flag: .\"dirty-flag\", bitmaps: .\"format-specific\".data.bitmaps}'; else qemu-img info -U --output=json %s; fi", + shellQuote(diskPath), shellQuote(diskPath))); + logTraceDiskCommandOutput(command, dummyVmName, phase, startedAt, i, diskPath, "qemu-img-check", String.format( + "qemu-img check %s", shellQuote(diskPath))); + } + } + + private void logTraceCommandOutput(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, long startedAt, String label, String traceCommand) { + Pair result = runCommandWithOutput(traceCommand); + String output = formatTraceOutput(result.second()); + if (result.first() == 0) { + LOGGER.info("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], command=[{}], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), + System.currentTimeMillis() - startedAt, label, output); + warnIfRuntimeBitmapLooksUnsafe(command, dummyVmName, phase, label, result.second()); + } else { + LOGGER.warn("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], command=[{}], exitCode=[{}], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), + System.currentTimeMillis() - startedAt, label, result.first(), output); + } + } + + private void logTraceDiskCommandOutput(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, long startedAt, int diskIndex, String diskPath, String label, String traceCommand) { + Pair result = runCommandWithOutput(traceCommand); + String output = formatTraceOutput(result.second()); + if (result.first() == 0) { + LOGGER.info("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], diskIndex=[{}], sourceDisk=[{}], command=[{}], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), + System.currentTimeMillis() - startedAt, diskIndex, diskPath, label, output); + warnIfOfflineBitmapLooksUnsafe(command, dummyVmName, phase, diskIndex, diskPath, label, result.second()); + } else { + LOGGER.warn("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], elapsedMillis=[{}], diskIndex=[{}], sourceDisk=[{}], command=[{}], exitCode=[{}], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), + System.currentTimeMillis() - startedAt, diskIndex, diskPath, label, result.first(), output); + } + } + + private void warnIfRuntimeBitmapLooksUnsafe(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, String label, String output) { + if (!"T3_AFTER_DOMJOB_COMPLETED".equals(phase)) { + return; + } + if (!"query-block".equals(label) && !"query-named-block-nodes".equals(label)) { + return; + } + if (output == null || output.isBlank()) { + return; + } + if (output.contains("\"busy\": true") || output.contains("\"inconsistent\": true") || output.contains("\"persistent\": false")) { + LOGGER.warn("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], command=[{}], bitmapWarning=[runtime bitmap may not be finalized], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), label, output); + } + } + + private void warnIfOfflineBitmapLooksUnsafe(AblestackNasTakeBackupCommand command, String dummyVmName, String phase, int diskIndex, String diskPath, String label, String output) { + if (!"qemu-img-info".equals(label) || output == null || output.isBlank()) { + return; + } + if (output.contains("\"in-use\"") || output.contains("in-use")) { + LOGGER.warn("[STOPPED_BACKUP_TRACE] phase=[{}], vm=[{}], dummyVm=[{}], backupType=[{}], checkpoint=[{}], diskIndex=[{}], sourceDisk=[{}], bitmapWarning=[offline qcow2 bitmap still has in-use flag], output=[{}]", + phase, command.getVmName(), dummyVmName, command.getBackupType(), command.getCheckpointName(), diskIndex, diskPath, output); + } + } + + private String formatTraceOutput(String output) { + if (output == null || output.isBlank()) { + return ""; + } + return output.replace("\r", "\\r").replace("\n", "\\n").trim(); + } + private String listTopLevelFileSizes(Path dest) throws IOException { try (var stream = Files.list(dest)) { return stream.filter(Files::isRegularFile) diff --git a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasRestoreBackupCommandWrapper.java b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasRestoreBackupCommandWrapper.java index fd2108638ccf..92cdeb856aa2 100644 --- a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasRestoreBackupCommandWrapper.java +++ b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasRestoreBackupCommandWrapper.java @@ -47,6 +47,7 @@ import java.io.IOException; import java.nio.file.Files; +import java.nio.file.Path; import java.nio.file.Paths; import java.util.ArrayList; import java.util.Arrays; @@ -65,6 +66,7 @@ public class LibvirtAblestackNasRestoreBackupCommandWrapper extends CommandWrapp private static final String ATTACH_QCOW2_DISK_COMMAND = " virsh attach-disk %s %s %s --driver qemu --subdriver qcow2 --cache none"; private static final String ATTACH_RBD_DISK_XML_COMMAND = " virsh attach-device %s /dev/stdin < volumeChainStates = command.getVolumeChainStates(); BackupRestorePlan restorePlan = command.getRestorePlan(); + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[ENTER], vm=[{}], backupPath=[{}], repoType=[{}], repoAddress=[{}], vmExists=[{}], restorePlan=[{}], volumePaths=[{}], restoreVolumePaths=[{}], backupFiles=[{}], backupFileChains=[{}]", + vmName, backupPath, backupRepoType, backupRepoAddress, vmExists, restorePlan, volumePaths, restoreVolumePaths, backupFiles, backupFileChains); String newVolumeId = null; try { validateChainStatePlan(volumeChainStates, restorePlan); @@ -113,6 +117,8 @@ public Answer execute(AblestackNasRestoreBackupCommand command, LibvirtComputing return new BackupAnswer(command, false, errorMessage); } + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[DONE], vm=[{}], backupPath=[{}], vmExists=[{}], newVolumeId=[{}]", + vmName, backupPath, vmExists, newVolumeId); return new BackupAnswer(command, true, newVolumeId); } @@ -296,6 +302,8 @@ private boolean replaceVolumeWithBackup(KVMStoragePoolManager storagePoolMgr, Pr if (backupPaths == null || backupPaths.isEmpty()) { return false; } + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[RESTORE_VOLUME_BEGIN], poolType=[{}], targetVolume=[{}], backupPaths=[{}], backupIndex=[{}], createTargetVolume=[{}]", + volumePool.getPoolType(), volumePath, backupPaths, backupIndex, createTargetVolume); if (volumePool.getPoolType() != Storage.StoragePoolType.RBD) { if (backupPaths.stream().anyMatch(path -> path.endsWith(".rbdiff"))) { return restoreIncrementalRbdBackupChainToFileVolume(volumePath, backupPaths, timeout, backupRootPath, backupIndex); @@ -334,16 +342,24 @@ private String getFirstExistingBackupPath(List backupPaths) { private boolean replaceFileVolumeWithBackup(String volumePath, String backupPath, int timeout) { QemuImgFile srcBackupFile = null; QemuImgFile destVolumeFile = null; + Path movedAsideTarget = null; try { - QemuImg qemu = new QemuImg(timeout * 1000, true, false); srcBackupFile = new QemuImgFile(backupPath, getBackupFileFormat(backupPath)); destVolumeFile = new QemuImgFile(volumePath, getFileVolumeFormat(volumePath)); - qemu.convert(srcBackupFile, destVolumeFile); + logger.info("Restoring NAS backup file [{}] to file volume [{}] without target-is-zero optimization.", backupPath, volumePath); + logFileRestoreQcow2State("BEFORE_SOURCE", backupPath, timeout); + logFileRestoreQcow2State("BEFORE_DEST", volumePath, timeout); + movedAsideTarget = moveExistingFileVolumeAside(volumePath); + restoreFileVolumeData(backupPath, volumePath, srcBackupFile.getFormat(), destVolumeFile.getFormat(), timeout); + logFileRestoreQcow2State("AFTER_SOURCE", backupPath, timeout); + logFileRestoreQcow2State("AFTER_DEST", volumePath, timeout); + deleteMovedAsideFileVolume(movedAsideTarget); return true; - } catch (QemuImgException | LibvirtException e) { + } catch (QemuImgException | IOException e) { String srcFilename = srcBackupFile != null ? srcBackupFile.getFileName() : null; String destFilename = destVolumeFile != null ? destVolumeFile.getFileName() : null; logger.error("Failed to convert backup {} to volume {}, the error was: {}", srcFilename, destFilename, e.getMessage()); + restoreMovedAsideFileVolume(volumePath, movedAsideTarget); return false; } } @@ -433,6 +449,141 @@ private boolean replaceRbdVolumeWithBackup(KVMStoragePoolManager storagePoolMgr, return true; } + private void logFileRestoreQcow2State(String phase, String imagePath, int timeout) { + logFileRestoreCommand(phase, imagePath, "qemu-img-info", String.format( + "qemu-img info -U --output=json %s", quote(imagePath)), timeout); + logFileRestoreCommand(phase, imagePath, "qemu-img-check", String.format( + "qemu-img check -U %s", quote(imagePath)), timeout); + } + + private Path moveExistingFileVolumeAside(String volumePath) throws IOException { + Path targetPath = Paths.get(volumePath); + if (!Files.exists(targetPath)) { + return null; + } + + Path movedAsidePath = targetPath.resolveSibling(targetPath.getFileName() + ".csrestore." + System.currentTimeMillis() + ".bak"); + Files.move(targetPath, movedAsidePath); + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[TARGET_MOVED_ASIDE], target=[{}], movedAside=[{}]", + volumePath, movedAsidePath); + return movedAsidePath; + } + + private void deleteMovedAsideFileVolume(Path movedAsideTarget) { + if (movedAsideTarget == null) { + return; + } + try { + Files.deleteIfExists(movedAsideTarget); + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[TARGET_MOVED_ASIDE_DELETED], movedAside=[{}]", movedAsideTarget); + } catch (IOException e) { + logger.warn("[ABLESTACK_NAS_RESTORE_TRACE] phase=[TARGET_MOVED_ASIDE_DELETE_FAILED], movedAside=[{}], error=[{}]", + movedAsideTarget, e.getMessage()); + } + } + + private void restoreMovedAsideFileVolume(String volumePath, Path movedAsideTarget) { + if (movedAsideTarget == null || !Files.exists(movedAsideTarget)) { + return; + } + Path targetPath = Paths.get(volumePath); + try { + Files.deleteIfExists(targetPath); + Files.move(movedAsideTarget, targetPath); + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[TARGET_MOVED_ASIDE_RESTORED], target=[{}], movedAside=[{}]", + volumePath, movedAsideTarget); + } catch (IOException e) { + logger.error("[ABLESTACK_NAS_RESTORE_TRACE] phase=[TARGET_MOVED_ASIDE_RESTORE_FAILED], target=[{}], movedAside=[{}], error=[{}]", + volumePath, movedAsideTarget, e.getMessage()); + } + } + + private void restoreFileVolumeData(String backupPath, String volumePath, QemuImg.PhysicalDiskFormat backupFormat, + QemuImg.PhysicalDiskFormat volumeFormat, int timeout) throws QemuImgException { + if (backupFormat == QemuImg.PhysicalDiskFormat.QCOW2 && volumeFormat == QemuImg.PhysicalDiskFormat.QCOW2) { + if (hasBackingChain(backupPath)) { + convertFileVolumeWithQemuImg(backupPath, volumePath, backupFormat, volumeFormat, timeout); + } else { + rsyncQcow2BackupFile(backupPath, volumePath, timeout); + } + return; + } + convertFileVolumeWithQemuImg(backupPath, volumePath, backupFormat, volumeFormat, timeout); + } + + private boolean hasBackingChain(String qcow2Path) { + return runCommandWithOutput(String.format(QEMU_IMG_HAS_BACKING_COMMAND, quote(qcow2Path)), 0).first() == 0; + } + + private void rsyncQcow2BackupFile(String backupPath, String volumePath, int timeout) throws QemuImgException { + String rsyncCommand = String.format("rsync -az %s %s", quote(backupPath), quote(volumePath)); + Pair result = runCommandWithOutput(rsyncCommand, timeout * 1000); + String output = formatTraceOutput(result.second()); + if (result.first() == 0) { + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[RSYNC], source=[{}], target=[{}], command=[rsync-qcow2], output=[{}]", + backupPath, volumePath, output); + return; + } + logger.warn("[ABLESTACK_NAS_RESTORE_TRACE] phase=[RSYNC], source=[{}], target=[{}], command=[rsync-qcow2], exitCode=[{}], output=[{}]", + backupPath, volumePath, result.first(), output); + throw new QemuImgException(String.format("rsync qcow2 backup failed with exitCode [%s], output [%s]", result.first(), output)); + } + + private void convertFileVolumeWithQemuImg(String backupPath, String volumePath, QemuImg.PhysicalDiskFormat backupFormat, + QemuImg.PhysicalDiskFormat volumeFormat, int timeout) throws QemuImgException { + String convertCommand = String.format("qemu-img convert -p -f %s -O %s %s %s", + backupFormat.toString().toLowerCase(Locale.ROOT), volumeFormat.toString().toLowerCase(Locale.ROOT), + quote(backupPath), quote(volumePath)); + Pair result = runCommandWithOutput(convertCommand, timeout * 1000); + String output = formatTraceOutput(result.second()); + if (result.first() == 0) { + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[CONVERT], source=[{}], target=[{}], command=[qemu-img-convert], output=[{}]", + backupPath, volumePath, output); + return; + } + logger.warn("[ABLESTACK_NAS_RESTORE_TRACE] phase=[CONVERT], source=[{}], target=[{}], command=[qemu-img-convert], exitCode=[{}], output=[{}]", + backupPath, volumePath, result.first(), output); + throw new QemuImgException(String.format("qemu-img convert failed with exitCode [%s], output [%s]", result.first(), output)); + } + + private void logFileRestoreCommand(String phase, String imagePath, String label, String traceCommand, int timeout) { + Pair result = runCommandWithOutput(traceCommand, timeout * 1000); + String output = formatTraceOutput(result.second()); + if (result.first() == 0) { + logger.info("[ABLESTACK_NAS_RESTORE_TRACE] phase=[{}], image=[{}], command=[{}], output=[{}]", + phase, imagePath, label, output); + } else { + logger.warn("[ABLESTACK_NAS_RESTORE_TRACE] phase=[{}], image=[{}], command=[{}], exitCode=[{}], output=[{}]", + phase, imagePath, label, result.first(), output); + } + } + + private Pair runCommandWithOutput(String command, int timeout) { + String wrappedCommand = String.format("set +e; %s 2>&1; rc=$?; echo __CMD_EXIT__=$rc", command); + String output = Script.runSimpleBashScriptWithFullResult(wrappedCommand, timeout); + if (output == null) { + return new Pair<>(-1, ""); + } + + List lines = new ArrayList<>(Arrays.asList(output.split("\n"))); + int exitCode = -1; + if (!lines.isEmpty()) { + String lastLine = lines.get(lines.size() - 1).trim(); + if (lastLine.startsWith("__CMD_EXIT__=")) { + exitCode = Integer.parseInt(lastLine.substring("__CMD_EXIT__=".length())); + lines.remove(lines.size() - 1); + } + } + return new Pair<>(exitCode, String.join("\n", lines).trim()); + } + + private String formatTraceOutput(String output) { + if (output == null || output.isBlank()) { + return ""; + } + return output.replace("\r", "\\r").replace("\n", "\\n").trim(); + } + private boolean importRawBackupToRbd(KVMStoragePool volumeStoragePool, String volumePath, String backupPath, int timeout, boolean createTargetVolume) { if (!createTargetVolume && !deleteExistingRbdVolumeIfPresent(volumeStoragePool, volumePath)) { logger.error("Failed to delete existing RBD volume {} before raw import", volumePath);