You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cloudstack.apache.org by ro...@apache.org on 2021/09/24 11:55:50 UTC
[cloudstack] branch main updated: backup: Improve Veeam Plugin logs
(#5455)
This is an automated email from the ASF dual-hosted git repository.
rohit pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/cloudstack.git
The following commit(s) were added to refs/heads/main by this push:
new c3a1c78 backup: Improve Veeam Plugin logs (#5455)
c3a1c78 is described below
commit c3a1c7862f6b490c4ee78b9796fd6aec0cd9a9ad
Author: SadiJr <31...@users.noreply.github.com>
AuthorDate: Fri Sep 24 08:55:27 2021 -0300
backup: Improve Veeam Plugin logs (#5455)
* Improve Veeam Plugin logs
* Address reviews
* Address reviews
Co-authored-by: SadiJr <sa...@scclouds.com.br>
---
.../cloudstack/backup/VeeamBackupProvider.java | 29 +++++++--
.../cloudstack/backup/veeam/VeeamClient.java | 41 ++++++++----
.../cloudstack/backup/BackupManagerImpl.java | 74 ++++++++++------------
3 files changed, 89 insertions(+), 55 deletions(-)
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 0b532a5..3781e20 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<VirtualMachine, Backup.Metric> getBackupMetrics(final Long zoneId, final List<VirtualMachine> vms) {
final Map<VirtualMachine, Backup.Metric> 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<String> 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<String, Backup.Metric> 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<Backup.RestorePoint> 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 1c0cc72..9facba5 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<Boolean, String> executePowerShellCommands(List<String> cmds) {
try {
- Pair<Boolean, String> pairResult = SshHelper.sshExecute(veeamServerIp, veeamServerPort,
+ String commands = transformPowerShellCommandList(cmds);
+ Pair<Boolean, String> 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<Backup.RestorePoint> listRestorePoints(String backupName, String vmInternalName) {
final List<String> 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<Boolean, String> response = executePowerShellCommands(cmds);
final List<Backup.RestorePoint> 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 e582765..154bbce 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<VMInstanceVO> 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);
}
}