diff --git a/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/VeeamBackupProvider.java b/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/VeeamBackupProvider.java index 0b532a52f95..3781e208d3d 100644 --- a/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/VeeamBackupProvider.java +++ b/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/VeeamBackupProvider.java @@ -24,17 +24,20 @@ import java.util.ArrayList; import java.util.HashMap; import java.util.List; import java.util.Map; +import java.util.Objects; import java.util.stream.Collectors; import javax.inject.Inject; import org.apache.cloudstack.api.InternalIdentity; +import org.apache.cloudstack.backup.Backup.Metric; import org.apache.cloudstack.backup.dao.BackupDao; import org.apache.cloudstack.backup.veeam.VeeamClient; import org.apache.cloudstack.backup.veeam.api.Job; import org.apache.cloudstack.framework.config.ConfigKey; import org.apache.cloudstack.framework.config.Configurable; import org.apache.commons.collections.CollectionUtils; +import org.apache.commons.lang3.BooleanUtils; import org.apache.log4j.Logger; import com.cloud.hypervisor.Hypervisor; @@ -149,7 +152,7 @@ public class VeeamBackupProvider extends AdapterBase implements BackupProvider, for (final BackupOffering job : client.listJobs()) { if (job.getName().equals(clonedJobName)) { final Job clonedJob = client.listJob(job.getExternalId()); - if (clonedJob.getScheduleConfigured() && !clonedJob.getScheduleEnabled()) { + if (BooleanUtils.isTrue(clonedJob.getScheduleConfigured()) && !clonedJob.getScheduleEnabled()) { client.toggleJobSchedule(clonedJob.getId()); } LOG.debug("Veeam job (backup offering) for backup offering ID: " + backupOffering.getExternalId() + " found, now trying to assign the VM to the job."); @@ -216,15 +219,24 @@ public class VeeamBackupProvider extends AdapterBase implements BackupProvider, @Override public Map getBackupMetrics(final Long zoneId, final List vms) { final Map metrics = new HashMap<>(); - if (vms == null || vms.isEmpty()) { + if (CollectionUtils.isEmpty(vms)) { + LOG.warn("Unable to get VM Backup Metrics because the list of VMs is empty."); return metrics; } + + List vmUuids = vms.stream().filter(Objects::nonNull).map(VirtualMachine::getUuid).collect(Collectors.toList()); + LOG.debug(String.format("Get Backup Metrics for VMs: [%s].", String.join(", ", vmUuids))); + final Map backendMetrics = getClient(zoneId).getBackupMetrics(); for (final VirtualMachine vm : vms) { if (vm == null || !backendMetrics.containsKey(vm.getUuid())) { continue; } - metrics.put(vm, backendMetrics.get(vm.getUuid())); + + Metric metric = backendMetrics.get(vm.getUuid()); + LOG.debug(String.format("Metrics for VM [uuid: %s, name: %s] is [backup size: %s, data size: %s].", vm.getUuid(), + vm.getInstanceName(), metric.getBackupSize(), metric.getDataSize())); + metrics.put(vm, metric); } return metrics; } @@ -237,7 +249,8 @@ public class VeeamBackupProvider extends AdapterBase implements BackupProvider, @Override public void syncBackups(VirtualMachine vm, Backup.Metric metric) { List restorePoints = listRestorePoints(vm); - if (restorePoints == null || restorePoints.isEmpty()) { + if (CollectionUtils.isEmpty(restorePoints)) { + LOG.debug(String.format("Can't find any restore point to VM: [uuid: %s, name: %s].", vm.getUuid(), vm.getInstanceName())); return; } Transaction.execute(new TransactionCallbackNoReturn() { @@ -252,6 +265,9 @@ public class VeeamBackupProvider extends AdapterBase implements BackupProvider, backupExists = true; removeList.remove(backup.getId()); if (metric != null) { + LOG.debug(String.format("Update backup with [uuid: %s, external id: %s] from [size: %s, protected size: %s] to [size: %s, protected size: %s].", + backup.getUuid(), backup.getExternalId(), backup.getSize(), backup.getProtectedSize(), metric.getBackupSize(), metric.getDataSize())); + ((BackupVO) backup).setSize(metric.getBackupSize()); ((BackupVO) backup).setProtectedSize(metric.getDataSize()); backupDao.update(backup.getId(), ((BackupVO) backup)); @@ -276,9 +292,14 @@ public class VeeamBackupProvider extends AdapterBase implements BackupProvider, backup.setAccountId(vm.getAccountId()); backup.setDomainId(vm.getDomainId()); backup.setZoneId(vm.getDataCenterId()); + + LOG.debug(String.format("Creating a new entry in backups: [uuid: %s, vm_id: %s, external_id: %s, type: %s, date: %s, backup_offering_id: %s, account_id: %s, " + + "domain_id: %s, zone_id: %s].", backup.getUuid(), backup.getVmId(), backup.getExternalId(), backup.getType(), backup.getDate(), + backup.getBackupOfferingId(), backup.getAccountId(), backup.getDomainId(), backup.getZoneId())); backupDao.persist(backup); } for (final Long backupIdToRemove : removeList) { + LOG.warn(String.format("Removing backup with ID: [%s].", backupIdToRemove)); backupDao.remove(backupIdToRemove); } } diff --git a/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/veeam/VeeamClient.java b/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/veeam/VeeamClient.java index 1c0cc72c16a..9facba529b4 100644 --- a/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/veeam/VeeamClient.java +++ b/plugins/backup/veeam/src/main/java/org/apache/cloudstack/backup/veeam/VeeamClient.java @@ -163,7 +163,7 @@ public class VeeamClient { if (!(response.getStatusLine().getStatusCode() == HttpStatus.SC_OK || response.getStatusLine().getStatusCode() == HttpStatus.SC_ACCEPTED) && response.getStatusLine().getStatusCode() != HttpStatus.SC_NO_CONTENT) { - LOG.debug("HTTP request failed, status code is " + response.getStatusLine().getStatusCode() + ", response is: " + response.toString()); + LOG.debug(String.format("HTTP request failed, status code is [%s], response is: [%s].", response.getStatusLine().getStatusCode(), response.toString())); throw new ServerApiException(ApiErrorCode.INTERNAL_ERROR, "Got invalid API status code returned by the Veeam server"); } } @@ -175,10 +175,13 @@ public class VeeamClient { } private HttpResponse get(final String path) throws IOException { - final HttpGet request = new HttpGet(apiURI.toString() + path); + String url = apiURI.toString() + path; + final HttpGet request = new HttpGet(url); request.setHeader(SESSION_HEADER, veeamSessionId); final HttpResponse response = httpClient.execute(request); checkAuthFailure(response); + + LOG.debug(String.format("Response received in GET request is: [%s] for URL: [%s].", response.toString(), url)); return response; } @@ -193,7 +196,8 @@ public class VeeamClient { xml = xml.replace(" xmlns=\"\"", ""); } - final HttpPost request = new HttpPost(apiURI.toString() + path); + String url = apiURI.toString() + path; + final HttpPost request = new HttpPost(url); request.setHeader(SESSION_HEADER, veeamSessionId); request.setHeader("Content-type", "application/xml"); if (StringUtils.isNotBlank(xml)) { @@ -202,14 +206,19 @@ public class VeeamClient { final HttpResponse response = httpClient.execute(request); checkAuthFailure(response); + + LOG.debug(String.format("Response received in POST request with body [%s] is: [%s] for URL [%s].", xml, response.toString(), url)); return response; } private HttpResponse delete(final String path) throws IOException { - final HttpDelete request = new HttpDelete(apiURI.toString() + path); + String url = apiURI.toString() + path; + final HttpDelete request = new HttpDelete(url); request.setHeader(SESSION_HEADER, veeamSessionId); final HttpResponse response = httpClient.execute(request); checkAuthFailure(response); + + LOG.debug(String.format("Response received in DELETE request is: [%s] for URL [%s].", response.toString(), url)); return response; } @@ -524,11 +533,18 @@ public class VeeamClient { */ protected Pair executePowerShellCommands(List cmds) { try { - Pair pairResult = SshHelper.sshExecute(veeamServerIp, veeamServerPort, + String commands = transformPowerShellCommandList(cmds); + Pair response = SshHelper.sshExecute(veeamServerIp, veeamServerPort, veeamServerUsername, null, veeamServerPassword, - transformPowerShellCommandList(cmds), - 120000, 120000, 3600000); - return pairResult; + commands, 120000, 120000, 3600000); + + if (response == null || !response.first()) { + LOG.error(String.format("Veeam PowerShell commands [%s] failed due to: [%s].", commands, response != null ? response.second() : "no PowerShell output returned")); + } else { + LOG.debug(String.format("Veeam response for PowerShell commands [%s] is: [%s].", commands, response.second())); + } + + return response; } catch (Exception e) { throw new CloudRuntimeException("Error while executing PowerShell commands due to: " + e.getMessage()); } @@ -595,6 +611,7 @@ public class VeeamClient { } private Backup.RestorePoint getRestorePointFromBlock(String[] parts) { + LOG.debug(String.format("Processing block of restore points: [%s].", StringUtils.join(parts, ", "))); String id = null; String created = null; String type = null; @@ -616,18 +633,20 @@ public class VeeamClient { public List listRestorePoints(String backupName, String vmInternalName) { final List cmds = Arrays.asList( String.format("$backup = Get-VBRBackup -Name \"%s\"", backupName), - String.format("if ($backup) { (Get-VBRRestorePoint -Backup:$backup -Name \"%s\" ^| Where-Object {$_.IsConsistent -eq $true}) }", vmInternalName) + String.format("if ($backup) { $restore = (Get-VBRRestorePoint -Backup:$backup -Name \"%s\" ^| Where-Object {$_.IsConsistent -eq $true})", vmInternalName), + "if ($restore) { $restore ^| Format-List } }" ); Pair response = executePowerShellCommands(cmds); final List restorePoints = new ArrayList<>(); if (response == null || !response.first()) { - LOG.debug("Veeam restore point listing failed due to: " + (response != null ? response.second() : "no powershell output returned")); return restorePoints; } + for (final String block : response.second().split("\r\n\r\n")) { if (block.isEmpty()) { continue; } + LOG.debug(String.format("Found restore points from [backupName: %s, vmInternalName: %s] which is: [%s].", backupName, vmInternalName, block)); final String[] parts = block.split("\r\n"); restorePoints.add(getRestorePointFromBlock(parts)); } @@ -651,4 +670,4 @@ public class VeeamClient { } return new Pair<>(result.first(), restoreLocation); } -} +} \ No newline at end of file diff --git a/server/src/main/java/org/apache/cloudstack/backup/BackupManagerImpl.java b/server/src/main/java/org/apache/cloudstack/backup/BackupManagerImpl.java index e582765f5ca..154bbced915 100644 --- a/server/src/main/java/org/apache/cloudstack/backup/BackupManagerImpl.java +++ b/server/src/main/java/org/apache/cloudstack/backup/BackupManagerImpl.java @@ -261,10 +261,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { @Override @ActionEvent(eventType = EventTypes.EVENT_VM_BACKUP_OFFERING_ASSIGN, eventDescription = "assign VM to backup offering", async = true) public boolean assignVMToBackupOffering(Long vmId, Long offeringId) { - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); - } + final VMInstanceVO vm = findVmById(vmId); if (!Arrays.asList(VirtualMachine.State.Running, VirtualMachine.State.Stopped, VirtualMachine.State.Shutdown).contains(vm.getState())) { throw new CloudRuntimeException("VM is not in running or stopped state"); @@ -313,7 +310,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { public boolean removeVMFromBackupOffering(final Long vmId, final boolean forced) { final VMInstanceVO vm = vmInstanceDao.findByIdIncludingRemoved(vmId); if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); + throw new CloudRuntimeException(String.format("Can't find any VM with ID: [%s].", vmId)); } validateForZone(vm.getDataCenterId()); @@ -330,8 +327,10 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { } if (!forced && backupProvider.willDeleteBackupsOnOfferingRemoval()) { - throw new CloudRuntimeException("The backend provider will only allow removal of VM from the offering if forced:true is provided " + - "that will also delete the backups."); + String message = String.format("To remove VM [id: %s, name: %s] from Backup Offering [id: %s, name: %s] using the provider [%s], please specify the " + + "forced:true option to allow the deletion of all jobs and backups for this VM or remove the backups that this VM has with the backup " + + "offering.", vm.getUuid(), vm.getInstanceName(), offering.getUuid(), offering.getName(), backupProvider.getClass().getSimpleName()); + throw new CloudRuntimeException(message); } boolean result = false; @@ -356,8 +355,9 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { } result = true; } - } catch (final Exception e) { - LOG.warn("Exception caught when trying to remove VM from the backup offering: ", e); + } catch (Exception e) { + LOG.error(String.format("Exception caught when trying to remove VM [uuid: %s, name: %s] from the backup offering [uuid: %s, name: %s] due to: [%s].", + vm.getUuid(), vm.getInstanceName(), offering.getUuid(), offering.getName(), e.getMessage()), e); } return result; } @@ -374,10 +374,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { throw new CloudRuntimeException("Invalid interval type provided"); } - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); - } + final VMInstanceVO vm = findVmById(vmId); validateForZone(vm.getDataCenterId()); accountManager.checkAccess(CallContext.current().getCallingAccount(), null, true, vm); @@ -417,10 +414,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { @Override public BackupSchedule listBackupSchedule(final Long vmId) { - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); - } + final VMInstanceVO vm = findVmById(vmId); validateForZone(vm.getDataCenterId()); accountManager.checkAccess(CallContext.current().getCallingAccount(), null, true, vm); @@ -430,10 +424,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { @Override @ActionEvent(eventType = EventTypes.EVENT_VM_BACKUP_SCHEDULE_DELETE, eventDescription = "deleting VM backup schedule") public boolean deleteBackupSchedule(final Long vmId) { - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); - } + final VMInstanceVO vm = findVmById(vmId); validateForZone(vm.getDataCenterId()); accountManager.checkAccess(CallContext.current().getCallingAccount(), null, true, vm); @@ -447,10 +438,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { @Override @ActionEvent(eventType = EventTypes.EVENT_VM_BACKUP_CREATE, eventDescription = "creating VM backup", async = true) public boolean createBackup(final Long vmId) { - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Did not find VM by provided ID"); - } + final VMInstanceVO vm = findVmById(vmId); validateForZone(vm.getDataCenterId()); accountManager.checkAccess(CallContext.current().getCallingAccount(), null, true, vm); @@ -605,10 +593,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { } validateForZone(backup.getZoneId()); - final VMInstanceVO vm = vmInstanceDao.findById(vmId); - if (vm == null) { - throw new CloudRuntimeException("Provided VM not found"); - } + final VMInstanceVO vm = findVmById(vmId); accountManager.checkAccess(CallContext.current().getCallingAccount(), null, true, vm); if (vm.getBackupOfferingId() != null) { @@ -674,7 +659,6 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { removeVMFromBackupOffering(vmId, true); } } - final BackupProvider backupProvider = getBackupProvider(offering.getProvider()); boolean result = backupProvider.deleteBackup(backup); if (result) { @@ -884,6 +868,10 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { final String nextScheduledTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, nextDateTime); LOG.debug("Next backup scheduled time for VM ID " + backupSchedule.getVmId() + " is " + nextScheduledTime); break; + default: + LOG.debug(String.format("Found async backup job [id: %s, vmId: %s] with status [%s] and cmd information: [cmd: %s, cmdInfo: %s].", asyncJob.getId(), backupSchedule.getVmId(), + asyncJob.getStatus(), asyncJob.getCmd(), asyncJob.getCmdInfo())); + break; } } } @@ -915,17 +903,15 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { final Account backupAccount = accountService.getAccount(vm.getAccountId()); if (backupAccount == null || backupAccount.getState() == Account.State.disabled) { - if (LOG.isDebugEnabled()) { - LOG.debug("Skip backup for VM " + vm.getUuid() + " since its account has been removed or disabled"); - } + LOG.debug(String.format("Skip backup for VM [uuid: %s, name: %s] since its account has been removed or disabled.", vm.getUuid(), vm.getInstanceName())); continue; } if (LOG.isDebugEnabled()) { final Date scheduledTimestamp = backupSchedule.getScheduledTimestamp(); displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, scheduledTimestamp); - LOG.debug("Scheduling 1 backup for VM ID " + vm.getId() + " (VM name:" + vm.getHostName() + - ") for backup schedule id: " + backupSchedule.getId() + " at " + displayTime); + LOG.debug(String.format("Scheduling 1 backup for VM [ID: %s, name: %s, hostName: %s] for backup schedule id: [%s] at [%s].", + vm.getId(), vm.getInstanceName(), vm.getHostName(), backupSchedule.getId(), displayTime)); } BackupScheduleVO tmpBackupScheduleVO = null; @@ -956,7 +942,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { tmpBackupScheduleVO.setAsyncJobId(jobId); backupScheduleDao.update(backupScheduleId, tmpBackupScheduleVO); } catch (Exception e) { - LOG.warn("Scheduling backup failed due to ", e); + LOG.error(String.format("Scheduling backup failed due to: [%s].", e.getMessage()), e); } finally { if (tmpBackupScheduleVO != null) { backupScheduleDao.releaseFromLockTable(backupScheduleId); @@ -989,6 +975,14 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { return true; } + private VMInstanceVO findVmById(final Long vmId) { + final VMInstanceVO vm = vmInstanceDao.findById(vmId); + if (vm == null) { + throw new CloudRuntimeException(String.format("Can't find any VM with ID: [%s].", vmId)); + } + return vm; + } + //////////////////////////////////////////////////// /////////////// Background Tasks /////////////////// //////////////////////////////////////////////////// @@ -1012,6 +1006,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { } for (final DataCenter dataCenter : dataCenterDao.listAllZones()) { if (dataCenter == null || isDisabled(dataCenter.getId())) { + LOG.debug(String.format("Backup Sync Task is not enabled in zone [%s]. Skipping this zone!", dataCenter == null ? "NULL Zone!" : dataCenter.getId())); continue; } @@ -1023,6 +1018,7 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { List vms = vmInstanceDao.listByZoneWithBackups(dataCenter.getId(), null); if (vms == null || vms.isEmpty()) { + LOG.debug(String.format("Can't find any VM to sync backups in zone [id: %s].", dataCenter.getId())); continue; } @@ -1041,13 +1037,11 @@ public class BackupManagerImpl extends ManagerBase implements BackupManager { } } } catch (final Throwable e) { - if (LOG.isTraceEnabled()) { - LOG.trace("Failed to sync backup usage metrics and out-of-band backups"); - } + LOG.error(String.format("Failed to sync backup usage metrics and out-of-band backups due to: [%s].", e.getMessage()), e); } } } catch (final Throwable t) { - LOG.error("Error trying to run backup-sync background task", t); + LOG.error(String.format("Error trying to run backup-sync background task due to: [%s].", t.getMessage()), t); } }