Skip to content

Log4j2 refactor cloud engine orchestration module #8742

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

Merged
DaanHoogland merged 9 commits into from
Apr 24, 2024
Merged

Log4j2 refactor cloud engine orchestration module #8742

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
db778e0
Refactor cloud-engine-orchestration module logs for Log4j2
Feb 16, 2024
f0231b8
adding some more log refactor
Mar 1, 2024
2cedec5
some more log refactoring for cloud-engine-orchestration module
Mar 4, 2024
2c10459
Merge branch 'main' into log4j2-refactor-cloud-engine-orchestration-m…
KlausDornsbach Mar 4, 2024
f323822
Merge branch 'main' into log4j2-refactor-cloud-engine-orchestration-m…
KlausDornsbach Mar 8, 2024
b677fd4
Merge branch 'main' into log4j2-refactor-cloud-engine-orchestration-m…
KlausDornsbach Apr 16, 2024
af2bfb7
addressing comments
Apr 19, 2024
3f0e309
addressing other comments
Apr 19, 2024
2e2ec00
fixing typo
Apr 22, 2024
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
32 changes: 15 additions & 17 deletions engine/orchestration/src/main/java/com/cloud/vm/VirtualMachineManagerImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1343,7 +1343,7 @@ public void orchestrateStart(final String vmUuid, final Map<VirtualMachineProfil
}
return;
} else {
logger.info("The guru did not like the answers so stopping " + vm);
logger.info("The guru did not like the answers so stopping {}", vm);
StopCommand stopCmd = new StopCommand(vm, getExecuteInSequence(vm.getHypervisorType()), false);
stopCmd.setControlIp(getControlNicIpForVM(vm));
Map<String, Boolean> vlanToPersistenceMap = getVlanToPersistenceMapForVM(vm.getId());
Expand Down Expand Up @@ -2429,7 +2429,7 @@ private Answer[] attemptHypervisorMigration(VMInstanceVO vm, Map<Volume, Storage
}

private void afterHypervisorMigrationCleanup(VMInstanceVO vm, Map<Volume, StoragePool> volumeToPool, Long sourceClusterId, Answer[] hypervisorMigrationResults) throws InsufficientCapacityException {
logger.debug("Cleaning up after hypervisor pool migration volumes for VM %s(%s)", vm.getInstanceName(), vm.getUuid());
logger.debug("Cleaning up after hypervisor pool migration volumes for VM {}({})", vm.getInstanceName(), vm.getUuid());

StoragePool rootVolumePool = null;
if (MapUtils.isNotEmpty(volumeToPool)) {
Expand All @@ -2443,7 +2443,7 @@ private void afterHypervisorMigrationCleanup(VMInstanceVO vm, Map<Volume, Storag
setDestinationPoolAndReallocateNetwork(rootVolumePool, vm);
Long destClusterId = rootVolumePool != null ? rootVolumePool.getClusterId() : null;
if (destClusterId != null && !destClusterId.equals(sourceClusterId)) {
logger.debug("Resetting lastHost for VM %s(%s)", vm.getInstanceName(), vm.getUuid());
logger.debug("Resetting lastHost for VM {}({})", vm.getInstanceName(), vm.getUuid());
vm.setLastHostId(null);
vm.setPodIdToDeployIn(rootVolumePool.getPodId());
}
Expand Down Expand Up @@ -4190,7 +4190,7 @@ private boolean orchestrateRemoveVmFromNetwork(final VirtualMachine vm, final Ne
throw new ConcurrentOperationException("Unable to lock nic " + nic.getId());
}

logger.debug("Lock is acquired for nic id " + lock.getId() + " as a part of remove vm " + vm + " from network " + network);
logger.debug("Lock is acquired for nic id {} as a part of remove vm {} from network {}", lock.getId(), vm, network);

try {
final NicProfile nicProfile =
Expand All @@ -4199,27 +4199,27 @@ private boolean orchestrateRemoveVmFromNetwork(final VirtualMachine vm, final Ne

if (vm.getState() == State.Running) {
final NicTO nicTO = toNicTO(nicProfile, vmProfile.getVirtualMachine().getHypervisorType());
logger.debug("Un-plugging nic for vm " + vm + " from network " + network);
logger.debug("Un-plugging nic for vm {} from network {}", vm, network);
final boolean result = unplugNic(network, nicTO, vmTO, context, dest);
if (result) {
logger.debug("Nic is unplugged successfully for vm " + vm + " in network " + network);
logger.debug("Nic is unplugged successfully for vm {} in network {}", vm, network);
} else {
logger.warn("Failed to unplug nic for the vm " + vm + " from network " + network);
logger.warn("Failed to unplug nic for the vm {} from network {}", vm, network);
return false;
}
} else if (vm.getState() != State.Stopped) {
logger.warn("Unable to remove vm " + vm + " from network " + network);
logger.warn("Unable to remove vm {} from network {}", vm, network);
throw new ResourceUnavailableException("Unable to remove vm " + vm + " from network, is not in the right state", DataCenter.class, vm.getDataCenterId());
}

_networkMgr.releaseNic(vmProfile, nic);
logger.debug("Successfully released nic " + nic + "for vm " + vm);
logger.debug("Successfully released nic {} for vm {}", nic, vm);

_networkMgr.removeNic(vmProfile, nic);
return true;
} finally {
_nicsDao.releaseFromLockTable(lock.getId());
logger.debug("Lock is released for nic id " + lock.getId() + " as a part of remove vm " + vm + " from network " + network);
logger.debug("Lock is released for nic id {} as a part of remove vm {} from network {}", lock.getId(), vm, network);
}
}

Expand Down Expand Up @@ -4259,7 +4259,7 @@ public void findHostAndMigrate(final String vmUuid, final Long newSvcOfferingId,
}

if (dest != null) {
logger.debug(" Found " + dest + " for scaling the vm to.");
logger.debug("Found {} for scaling the vm to.", dest);
}

if (dest == null) {
Expand Down Expand Up @@ -5296,7 +5296,7 @@ public Outcome<VirtualMachine> addVmToNetworkThroughJobQueue(
}
workJob = pendingWorkJobs.get(0);
} else {
logger.trace(String.format("no jobs to add network %s for vm %s yet", network, vm));
logger.trace("no jobs to add network {} for vm {} yet", network, vm);

workJob = createVmWorkJobToAddNetwork(vm, network, requested, context, user, account);
}
Expand Down Expand Up @@ -5600,7 +5600,7 @@ public UserVm restoreVirtualMachine(final long vmId, final Long newTemplateId, f
}

private UserVm orchestrateRestoreVirtualMachine(final long vmId, final Long newTemplateId, final Long rootDiskOfferingId, final boolean expunge, final Map<String, String> details) throws ResourceUnavailableException, InsufficientCapacityException {
logger.debug("Restoring vm " + vmId + " with templateId : " + newTemplateId + " diskOfferingId : " + rootDiskOfferingId + " details : " + details);
logger.debug("Restoring vm {} with templateId: {}, diskOfferingId: {}, details: {}", vmId, newTemplateId, rootDiskOfferingId, details);
final CallContext context = CallContext.current();
final Account account = context.getCallingAccount();
return _userVmService.restoreVirtualMachine(account, vmId, newTemplateId, rootDiskOfferingId, expunge, details);
Expand Down Expand Up @@ -5668,7 +5668,7 @@ public Boolean updateDefaultNicForVM(final VirtualMachine vm, final Nic nic, fin

private Boolean orchestrateUpdateDefaultNicForVM(final VirtualMachine vm, final Nic nic, final Nic defaultNic) {

logger.debug("Updating default nic of vm " + vm + " from nic " + defaultNic.getUuid() + " to nic " + nic.getUuid());
logger.debug("Updating default nic of vm {} from nic {} to nic {}", vm, defaultNic.getUuid(), nic.getUuid());
Integer chosenID = nic.getDeviceId();
Integer existingID = defaultNic.getDeviceId();
NicVO nicVO = _nicsDao.findById(nic.getId());
Expand Down Expand Up @@ -6015,9 +6015,7 @@ protected boolean isDiskOfferingSuitableForVm(VMInstanceVO vm, VirtualMachinePro
for (StoragePoolAllocator allocator : _storagePoolAllocators) {
List<StoragePool> poolListFromAllocator = allocator.allocateToPool(diskProfile, profile, plan, avoid, 1);
if (CollectionUtils.isNotEmpty(poolListFromAllocator)) {
if (logger.isDebugEnabled()) {
logger.debug(String.format("Found a suitable pool: %s for disk offering: %s", poolListFromAllocator.get(0).getName(), diskOffering.getName()));
}
logger.debug("Found a suitable pool: {} for disk offering: {}", poolListFromAllocator.get(0).getName(), diskOffering.getName());
return true;
}
}
Expand Down
39 changes: 19 additions & 20 deletions engine/orchestration/src/main/java/com/cloud/vm/VirtualMachinePowerStateSyncImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,40 +47,40 @@ public VirtualMachinePowerStateSyncImpl() {

@Override
public void resetHostSyncState(long hostId) {
logger.info("Reset VM power state sync for host: " + hostId);
logger.info("Reset VM power state sync for host: {}.", hostId);
_instanceDao.resetHostPowerStateTracking(hostId);
}

@Override
public void processHostVmStateReport(long hostId, Map<String, HostVmStateReportEntry> report) {
logger.debug("Process host VM state report. host: " + hostId);
logger.debug("Process host VM state report. host: {}.", hostId);

Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(report);
processReport(hostId, translatedInfo, false);
}

@Override
public void processHostVmStatePingReport(long hostId, Map<String, HostVmStateReportEntry> report, boolean force) {
logger.debug("Process host VM state report from ping process. host: " + hostId);
logger.debug("Process host VM state report from ping process. host: {}.", hostId);

Map<Long, VirtualMachine.PowerState> translatedInfo = convertVmStateReport(report);
processReport(hostId, translatedInfo, force);
}

private void processReport(long hostId, Map<Long, VirtualMachine.PowerState> translatedInfo, boolean force) {

logger.debug("Process VM state report. host: " + hostId + ", number of records in report: " + translatedInfo.size());
logger.debug("Process VM state report. host: {}, number of records in report: {}.", hostId, translatedInfo.size());

for (Map.Entry<Long, VirtualMachine.PowerState> entry : translatedInfo.entrySet()) {

logger.debug("VM state report. host: " + hostId + ", vm id: " + entry.getKey() + ", power state: " + entry.getValue());
logger.debug("VM state report. host: {}, vm id: {}, power state: {}.", hostId, entry.getKey(), entry.getValue());

if (_instanceDao.updatePowerState(entry.getKey(), hostId, entry.getValue(), DateUtil.currentGMTTime())) {
logger.debug("VM state report is updated. host: " + hostId + ", vm id: " + entry.getKey() + ", power state: " + entry.getValue());
logger.debug("VM state report is updated. host: {}, vm id: {}, power state: {}.", hostId, entry.getKey(), entry.getValue());

_messageBus.publish(null, VirtualMachineManager.Topics.VM_POWER_STATE, PublishScope.GLOBAL, entry.getKey());
} else {
logger.trace("VM power state does not change, skip DB writing. vm id: " + entry.getKey());
logger.trace("VM power state does not change, skip DB writing. vm id: {}.", entry.getKey());
}
}

Expand All @@ -99,7 +99,7 @@ private void processReport(long hostId, Map<Long, VirtualMachine.PowerState> tra
// here we need to be wary of out of band migration as opposed to other, more unexpected state changes
if (vmsThatAreMissingReport.size() > 0) {
Date currentTime = DateUtil.currentGMTTime();
logger.debug("Run missing VM report. current time: " + currentTime.getTime());
logger.debug("Run missing VM report. current time: {}", currentTime.getTime());

// 2 times of sync-update interval for graceful period
long milliSecondsGracefullPeriod = mgmtServiceConf.getPingInterval() * 2000L;
Expand All @@ -109,7 +109,7 @@ private void processReport(long hostId, Map<Long, VirtualMachine.PowerState> tra
// Make sure powerState is up to date for missing VMs
try {
if (!force && !_instanceDao.isPowerStateUpToDate(instance.getId())) {
logger.warn("Detected missing VM but power state is outdated, wait for another process report run for VM id: " + instance.getId());
logger.warn("Detected missing VM but power state is outdated, wait for another process report run for VM id: {}.", instance.getId());
_instanceDao.resetVmPowerStateTracking(instance.getId());
continue;
}
Expand All @@ -120,45 +120,44 @@ private void processReport(long hostId, Map<Long, VirtualMachine.PowerState> tra

Date vmStateUpdateTime = instance.getPowerStateUpdateTime();
if (vmStateUpdateTime == null) {
logger.warn("VM power state update time is null, falling back to update time for vm id: " + instance.getId());
logger.warn("VM power state update time is null, falling back to update time for vm id: {}.", instance.getId());
vmStateUpdateTime = instance.getUpdateTime();
if (vmStateUpdateTime == null) {
logger.warn("VM update time is null, falling back to creation time for vm id: " + instance.getId());
logger.warn("VM update time is null, falling back to creation time for vm id: {}", instance.getId());
vmStateUpdateTime = instance.getCreated();
}
}

String lastTime = new SimpleDateFormat("yyyy/MM/dd'T'HH:mm:ss.SSS'Z'").format(vmStateUpdateTime);
logger.debug(
String.format("Detected missing VM. host: %d, vm id: %d(%s), power state: %s, last state update: %s"
logger.debug("Detected missing VM. host: {}, vm id: {}({}), power state: {}, last state update: {}"
, hostId
, instance.getId()
, instance.getUuid()
, VirtualMachine.PowerState.PowerReportMissing
, lastTime));
, lastTime);

long milliSecondsSinceLastStateUpdate = currentTime.getTime() - vmStateUpdateTime.getTime();

if (force || milliSecondsSinceLastStateUpdate > milliSecondsGracefullPeriod) {
logger.debug("vm id: " + instance.getId() + " - time since last state update(" + milliSecondsSinceLastStateUpdate + "ms) has passed graceful period");
logger.debug("vm id: {} - time since last state update({}ms) has passed graceful period.", instance.getId(), milliSecondsSinceLastStateUpdate);

// this is were a race condition might have happened if we don't re-fetch the instance;
// between the startime of this job and the currentTime of this missing-branch
// an update might have occurred that we should not override in case of out of band migration
if (_instanceDao.updatePowerState(instance.getId(), hostId, VirtualMachine.PowerState.PowerReportMissing, startTime)) {
logger.debug("VM state report is updated. host: " + hostId + ", vm id: " + instance.getId() + ", power state: PowerReportMissing ");
logger.debug("VM state report is updated. host: {}, vm id: {}, power state: PowerReportMissing.", hostId, instance.getId());

_messageBus.publish(null, VirtualMachineManager.Topics.VM_POWER_STATE, PublishScope.GLOBAL, instance.getId());
} else {
logger.debug("VM power state does not change, skip DB writing. vm id: " + instance.getId());
logger.debug("VM power state does not change, skip DB writing. vm id: {}", instance.getId());
}
} else {
logger.debug("vm id: " + instance.getId() + " - time since last state update(" + milliSecondsSinceLastStateUpdate + "ms) has not passed graceful period yet");
logger.debug("vm id: {} - time since last state update({}ms) has not passed graceful period yet.", instance.getId(), milliSecondsSinceLastStateUpdate);
}
}
}

logger.debug("Done with process of VM state report. host: " + hostId);
logger.debug("Done with process of VM state report. host: {}", hostId);
}

@Override
Expand All @@ -173,7 +172,7 @@ public Map<Long, VirtualMachine.PowerState> convertVmStateReport(Map<String, Hos
if (vm != null) {
map.put(vm.getId(), entry.getValue().getState());
} else {
logger.debug("Unable to find matched VM in CloudStack DB. name: " + entry.getKey());
logger.debug("Unable to find matched VM in CloudStack DB. name: {}", entry.getKey());
}
}

Expand Down
Loading