backup: Improve Veeam Plugin logs (#5455)

* Improve Veeam Plugin logs

* Address reviews

* Address reviews

Co-authored-by: SadiJr <sadi@scclouds.com.br>

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);
                 }
             }

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),
+                    commands, 120000, 120000, 3600000);
-                    120000, 120000, 3600000);
+
-            return pairResult;
+            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));
         }

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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Did not find VM by provided ID");
-        }
 
         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 " +
+            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 "
-                    "that will also delete the backups.");
+                    + "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) {
+        } catch (Exception e) {
-            LOG.warn("Exception caught when trying to remove VM from the backup offering: ", 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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Did not find VM by provided ID");
-        }
         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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Did not find VM by provided ID");
-        }
         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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Did not find VM by provided ID");
-        }
         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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Did not find VM by provided ID");
-        }
         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);
+        final VMInstanceVO vm = findVmById(vmId);
-        if (vm == null) {
-            throw new CloudRuntimeException("Provided VM not found");
-        }
         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(String.format("Skip backup for VM [uuid: %s, name: %s] since its account has been removed or disabled.", vm.getUuid(), vm.getInstanceName()));
-                    LOG.debug("Skip backup for VM " + vm.getUuid() + " since its account has been removed or disabled");
-                }
                 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() +
+                LOG.debug(String.format("Scheduling 1 backup for VM [ID: %s, name: %s, hostName: %s] for backup schedule id: [%s] at [%s].",
-                        ") for backup schedule id: " + backupSchedule.getId() + " at " + displayTime);
+                        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.error(String.format("Failed to sync backup usage metrics and out-of-band backups due to: [%s].", e.getMessage()), e);
-                            LOG.trace("Failed to sync backup usage metrics and out-of-band backups");
-                        }
                     }
                 }
             } 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);
             }
         }