From e4e3852854bb3ca70654732e7dea0669950fea32 Mon Sep 17 00:00:00 2001 From: Jie Shen Date: Fri, 14 Dec 2018 09:40:28 +0800 Subject: [PATCH] Wrap the log level for periodic work --- .../vmagent/AzureVMAgentCleanUpTask.java | 41 ++++++++++--------- .../vmagent/AzureVMCloudVerificationTask.java | 29 +++++++------ .../vmagent/AzureVMMaintainPoolTask.java | 6 +-- 3 files changed, 41 insertions(+), 35 deletions(-) diff --git a/src/main/java/com/microsoft/azure/vmagent/AzureVMAgentCleanUpTask.java b/src/main/java/com/microsoft/azure/vmagent/AzureVMAgentCleanUpTask.java index 6a2ce1c7..ad5794ee 100644 --- a/src/main/java/com/microsoft/azure/vmagent/AzureVMAgentCleanUpTask.java +++ b/src/main/java/com/microsoft/azure/vmagent/AzureVMAgentCleanUpTask.java @@ -210,7 +210,7 @@ public void cleanDeployments() { } public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMinutes) { - LOGGER.log(Level.INFO, "AzureVMAgentCleanUpTask: cleanDeployments: Cleaning deployments"); + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Cleaning deployments"); // Walk the queue, popping and pushing until we reach an item that we've already // dealt with or the queue is empty. DeploymentInfo firstBackInQueue = null; @@ -219,7 +219,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin while (!deploymentsToClean.isEmpty() && firstBackInQueue != deploymentsToClean.peek()) { DeploymentInfo info = deploymentsToClean.remove(); - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Checking deployment {0}", info.getDeploymentName()); @@ -245,19 +245,19 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin deployment = azureClient.deployments(). getByResourceGroup(info.getResourceGroupName(), info.getDeploymentName()); } catch (NullPointerException e) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Deployment not found, skipping"); continue; } if (deployment == null) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Deployment not found, skipping"); continue; } DateTime deploymentTime = deployment.timestamp(); - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Deployment created on {0}", deploymentTime.toDate()); long deploymentTimeInMillis = deploymentTime.getMillis(); @@ -272,7 +272,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin String state = deployment.provisioningState(); if (!state.equalsIgnoreCase("succeeded") && diffTimeInMinutes > failTimeoutInMinutes) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: " + "Failed deployment older than {0} minutes, deleting", failTimeoutInMinutes); @@ -284,7 +284,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin } } else if (state.equalsIgnoreCase("succeeded") && diffTimeInMinutes > successTimeoutInMinutes) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: " + "Successful deployment older than {0} minutes, deleting", successTimeoutInMinutes); @@ -295,7 +295,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin delegate.removeStorageBlob(new URI(info.scriptUri), info.getResourceGroupName()); } } else { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Deployment newer than timeout, keeping"); if (firstBackInQueue == null) { @@ -305,7 +305,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin deploymentsToClean.add(info); } } catch (Exception e) { - LOGGER.log(Level.INFO, + LOGGER.log(Level.WARNING, "AzureVMAgentCleanUpTask: cleanDeployments: Failed to get/delete deployment: {0}", e); // Check the number of attempts remaining. If greater than 0, decrement @@ -324,7 +324,7 @@ public void cleanDeployments(long successTimeoutInMinutes, long failTimeoutInMin } DeploymentRegistrar.getInstance().syncDeploymentsToClean(); - LOGGER.log(Level.INFO, "AzureVMAgentCleanUpTask: cleanDeployments: Done cleaning deployments"); + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanDeployments: Done cleaning deployments"); } /* There are some edge-cases where we might loose track of the provisioned resources: @@ -445,7 +445,7 @@ private int getPriority(GenericResource resource) { } } - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "cleanLeakedResources: deleting {0} from resource group {1}", new Object[]{resource.name(), resourceGroup}); azureClient.genericResources().deleteById(resource.id()); @@ -495,7 +495,7 @@ private void cleanVMs(ExecutionEngine executionEngine) { // Even if offline, a machine that has been temporarily marked offline // should stay (this could be for investigation). if (azureComputer.isSetOfflineByUser()) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanVMs: node {0} was set offline by user, skipping", agentNode.getDisplayName()); continue; @@ -503,7 +503,7 @@ private void cleanVMs(ExecutionEngine executionEngine) { // If the machine is in "keep" state, skip if (agentNode.isCleanUpBlocked()) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanVMs: node {0} blocked to cleanup", agentNode.getDisplayName()); continue; @@ -512,7 +512,7 @@ private void cleanVMs(ExecutionEngine executionEngine) { // Check if the virtual machine exists. If not, it could have been // deleted in the background. Remove from Jenkins if that is the case. if (!AzureVMManagementServiceDelegate.virtualMachineExists(agentNode)) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanVMs: node {0} doesn't exist, removing", agentNode.getDisplayName()); try { @@ -532,12 +532,12 @@ private void cleanVMs(ExecutionEngine executionEngine) { public Void call() throws Exception { // Depending on the cleanup action, run the appropriate if (agentNode.getCleanUpAction() == CleanUpAction.DELETE) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanVMs: deleting {0}", agentNode.getDisplayName()); agentNode.deprovision(agentNode.getCleanUpReason()); } else if (agentNode.getCleanUpAction() == CleanUpAction.SHUTDOWN) { - LOGGER.log(Level.INFO, + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: cleanVMs: shutting down {0}", agentNode.getDisplayName()); agentNode.shutdown(agentNode.getCleanUpReason()); @@ -562,7 +562,7 @@ public Void call() throws Exception { )); } catch (AzureCloudException exception) { // No need to throw exception back, just log and move on. - LOGGER.log(Level.INFO, + LOGGER.log(Level.WARNING, "AzureVMAgentCleanUpTask: cleanVMs: failed to shutdown/delete " + agentNode.getDisplayName(), exception); @@ -624,7 +624,7 @@ private void clean() { @Override public void execute(TaskListener arg0) throws InterruptedException { - LOGGER.log(Level.INFO, "AzureVMAgentCleanUpTask: execute: start"); + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: execute: start"); Callable callClean = new Callable() { @Override @@ -637,7 +637,8 @@ public Void call() throws Exception { Future result = AzureVMCloud.getThreadPool().submit(callClean); try { - LOGGER.info("AzureVMAgentCleanUpTask: execute: Running clean with 5 minute timeout"); + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: execute: Running clean with 5 minute " + + "timeout"); // Get will block until time expires or until task completes result.get(CLEAN_TIMEOUT_IN_MINUTES, TimeUnit.MINUTES); } catch (ExecutionException executionException) { @@ -654,7 +655,7 @@ public Void call() throws Exception { others); } - LOGGER.info("AzureVMAgentCleanUpTask: execute: end"); + LOGGER.log(getNormalLoggingLevel(), "AzureVMAgentCleanUpTask: execute: end"); } @Override diff --git a/src/main/java/com/microsoft/azure/vmagent/AzureVMCloudVerificationTask.java b/src/main/java/com/microsoft/azure/vmagent/AzureVMCloudVerificationTask.java index c7d58d65..d19109da 100644 --- a/src/main/java/com/microsoft/azure/vmagent/AzureVMCloudVerificationTask.java +++ b/src/main/java/com/microsoft/azure/vmagent/AzureVMCloudVerificationTask.java @@ -47,14 +47,14 @@ public static void verify(String cloudName, String templateName) { final AzureVMCloud cloud = getCloud(cloudName); if (cloud == null) { - LOGGER.log(Level.INFO, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: parent cloud not found for {0} in {1}", new Object[]{templateName, cloudName}); return; } final AzureVMAgentTemplate agentTemplate = cloud.getAzureAgentTemplate(templateName); if (agentTemplate == null) { - LOGGER.log(Level.INFO, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: " + "could not retrieve agent template named {0} in {1}", new Object[]{templateName, cloudName}); @@ -81,7 +81,7 @@ public static void verify(String cloudName, String templateName) { try { List errors = agentTemplate.verifyTemplate(); if (errors.isEmpty()) { - LOGGER.log(Level.FINE, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: {0} verified successfully", templateName); // Verified, set the template to verified. @@ -111,7 +111,7 @@ private static void verifyCloud(String cloudName) { if (StringUtils.isBlank(cloudName)) { return; } - LOGGER.log(Level.FINE, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: verifying cloud {0}", cloudName); @@ -119,7 +119,7 @@ private static void verifyCloud(String cloudName) { // Unknown cloud. Maybe the name changed if (cloud == null) { - LOGGER.log(Level.INFO, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: subscription {0} not found, skipping", cloudName); return; @@ -128,7 +128,7 @@ private static void verifyCloud(String cloudName) { synchronized (cloud) { // Only if verified pass, return at once if (cloud.getConfigurationStatus().equals(Constants.VERIFIED_PASS)) { - LOGGER.log(Level.FINE, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verify: cloud {0} already verified pass", cloudName); // Update the count. @@ -138,7 +138,8 @@ private static void verifyCloud(String cloudName) { // Verify. Update the VM count before setting to valid if (verifyConfiguration(cloud)) { - LOGGER.log(Level.FINE, "AzureVMCloudVerificationTask: validate: {0} verified pass", cloudName); + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: validate: {0} " + + "verified pass", cloudName); // Update the count cloud.setVirtualMachineCount(getVirtualMachineCount(cloud)); // We grab the current VM count and @@ -163,7 +164,7 @@ private static void verifyCloud(String cloudName) { * return */ public static boolean verifyConfiguration(AzureVMCloud cloud) { - LOGGER.info("AzureVMCloudVerificationTask: verifyConfiguration: start"); + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verifyConfiguration: start"); // Check the sub and off we go String result = cloud.getServiceDelegate().verifyConfiguration( @@ -171,7 +172,7 @@ public static boolean verifyConfiguration(AzureVMCloud cloud) { Integer.toString(cloud.getMaxVirtualMachinesLimit()), Integer.toString(cloud.getDeploymentTimeout())); if (!Constants.OP_SUCCESS.equals(result)) { - LOGGER.log(Level.INFO, "AzureVMCloudVerificationTask: verifyConfiguration: {0}", result); + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: verifyConfiguration: {0}", result); cloud.setConfigurationStatus(Constants.VERIFIED_FAILED); return false; } @@ -186,16 +187,16 @@ public static boolean verifyConfiguration(AzureVMCloud cloud) { * @return The current VM count */ public static int getVirtualMachineCount(AzureVMCloud cloud) { - LOGGER.info("AzureVMCloudVerificationTask: getVirtualMachineCount: start"); + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: getVirtualMachineCount: start"); try { int vmCount = cloud.getServiceDelegate().getVirtualMachineCount(cloud.getCloudName(), cloud.getResourceGroupName()); - LOGGER.log(Level.INFO, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: getVirtualMachineCount: end, cloud {0} has currently {1} vms", new Object[]{cloud.getCloudName(), vmCount}); return vmCount; } catch (Exception e) { - LOGGER.log(Level.INFO, + LOGGER.log(getStaticNormalLoggingLevel(), "AzureVMCloudVerificationTask: getVirtualMachineCount: failed to retrieve vm count:\n{0}", e.toString()); // We could have failed for any number of reasons. Just return the current @@ -230,4 +231,8 @@ public long getRecurrencePeriod() { protected Level getNormalLoggingLevel() { return Level.FINE; } + + private static Level getStaticNormalLoggingLevel() { + return Level.FINE; + } } diff --git a/src/main/java/com/microsoft/azure/vmagent/AzureVMMaintainPoolTask.java b/src/main/java/com/microsoft/azure/vmagent/AzureVMMaintainPoolTask.java index cd1b6c6d..7e536cf7 100644 --- a/src/main/java/com/microsoft/azure/vmagent/AzureVMMaintainPoolTask.java +++ b/src/main/java/com/microsoft/azure/vmagent/AzureVMMaintainPoolTask.java @@ -27,12 +27,12 @@ public AzureVMMaintainPoolTask() { } public void maintain(AzureVMCloud cloud, AzureVMAgentTemplate template) { - LOGGER.log(Level.INFO, "Starting to maintain template: {0}", template.getTemplateName()); + LOGGER.log(getNormalLoggingLevel(), "Starting to maintain template: {0}", template.getTemplateName()); int currentSize = 0; final int sizeLimit = ((AzureVMCloudPoolRetentionStrategy) template.getRetentionStrategy()).getPoolSize(); if (PoolLock.checkProvisionLock(template)) { - LOGGER.log(Level.INFO, "Agents of template {0} is creating, check later", template); + LOGGER.log(getNormalLoggingLevel(), "Agents of template {0} is creating, check later", template); return; } @@ -48,7 +48,7 @@ public void maintain(AzureVMCloud cloud, AzureVMAgentTemplate template) { } } if (currentSize < sizeLimit) { - LOGGER.log(Level.INFO, "Prepare for provisioning {0} agents for template {1}", + LOGGER.log(getNormalLoggingLevel(), "Prepare for provisioning {0} agents for template {1}", new Object[]{sizeLimit - currentSize, template.getTemplateName()}); provisionNodes(cloud, template, sizeLimit - currentSize); }