Skip to content

[Mold] qemu-img convert 기반 qocw2 복원 시 mismatch가 발생하는 이슈로 rsync 기반으로 복원하도록 개선 #887

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Dajeong-Park wants to merge 10 commits into
base: ablestack-europa
Choose a base branch
from
Open

[Mold] qemu-img convert 기반 qocw2 복원 시 mismatch가 발생하는 이슈로 rsync 기반으로 복원하도록 개선 #887

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
22754e8
Update LibvirtAblestackNasBackupHelper.java
Dajeong-Park Aug 12, 2026
8e41ca4
NAS file-volume restore 시 target-is-zero 최적화 끔
Dajeong-Park Aug 12, 2026
1165f8e
테스트로그 추가
Dajeong-Park Aug 12, 2026
e9e2676
복원시 파일 덮어쓰지않도록 변경
Dajeong-Park Aug 12, 2026
ced3b77
패치 실패시 bak 원복 확인, 이후에도 원인 동일하여 명시적으로 shell 실행
Dajeong-Park Aug 12, 2026
d560024
결과 동일하여, convert 제외하고 동일한 포맷일때 exact copy수행
Dajeong-Park Aug 12, 2026
4d8ee5a
복원 흐름은 cp로 변경하며, 진단 convert 호출 추가
Dajeong-Park Aug 12, 2026
ebe7c40
cp 에서 rsync 방식으로 변경
Dajeong-Park Aug 13, 2026
dc3248f
convert 진단코드 삭제
Dajeong-Park Aug 13, 2026
ca5beb0
테스트 compare 코드 삭제
Dajeong-Park Aug 13, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
138 changes: 136 additions & 2 deletions .../main/java/com/cloud/hypervisor/kvm/resource/wrapper/LibvirtAblestackNasBackupHelper.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -217,6 +217,7 @@ private Pair<Integer, String> 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());
Expand All @@ -228,10 +229,16 @@ private Pair<Integer, String> 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()));
Expand All @@ -252,10 +259,16 @@ private Pair<Integer, String> 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;
Expand All @@ -266,11 +279,18 @@ private Pair<Integer, String> 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);
Expand All @@ -284,7 +304,12 @@ private Pair<Integer, String> 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);
}
}
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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<String> 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<Integer, String> 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<Integer, String> 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)
Expand Down
Loading
Loading