Prefix Anka logs with [Anka]; improve Advanced cloud config UI

- Add AnkaLog / AnkaSdkLog and use for plugin and ankaMgmtSdk INFO/FINE/WARNING lines
- Cloud Log() output gets the same prefix via AnkaMgmtCloud
- Jenkins cloud config: use f:advanced instead of optionalBlock; widen advanced panel; hide repeated-chunk__header padding
- Provisioning: log when cloud/template capacity blocks provisioning and when no cloud can provision a label
- AnkaPlannedNodeCreator: terminate instance on InterruptedException during provisioning wait

Author: NorseGaud

src/main/java/com/veertu/ankaMgmtSdk/AnkaAPI.java

@@ -90,7 +90,7 @@ public String startVM(String templateId, String tag, String startUpScript, Strin
     }
 
     public boolean terminateInstance(String vmId) throws AnkaMgmtException {
-        LOGGER.info("Sending termination request to instance: " + vmId);
+        LOGGER.info(AnkaSdkLog.prefix("Sending termination request to instance: " + vmId));
         boolean result = communicator.terminateVm(vmId);
         invalidateCache();
         return result;

src/main/java/com/veertu/ankaMgmtSdk/AnkaSdkLog.java

@@ -0,0 +1,15 @@
+package com.veertu.ankaMgmtSdk;
+
+final class AnkaSdkLog {
+    private static final String PREFIX = "[Anka] ";
+
+    private AnkaSdkLog() {
+    }
+
+    static String prefix(String message) {
+        if (message == null || message.startsWith(PREFIX)) {
+            return message;
+        }
+        return PREFIX + message;
+    }
+}

src/main/java/com/veertu/ankaMgmtSdk/ConcAnkaMgmtVm.java

@@ -28,7 +28,7 @@ public ConcAnkaMgmtVm(String sessionId, AnkaMgmtCommunicator communicator, int s
         this.sessionId = sessionId;
         this.sshConnectionPort = sshConnectionPort;
         this.terminated = false;
-        logger.info(String.format("init VM %s", sessionId));
+        logger.info(AnkaSdkLog.prefix(String.format("init VM %s", sessionId)));
     }
 
     public String getStatus() throws AnkaMgmtException {
@@ -72,7 +72,7 @@ private AnkaVmInstance getSessionInfoCache() {
                 if (session != null) {
                     this.cachedVmSession = session;
                 } else {
-                    logger.info("info for vm is null");
+                    logger.info(AnkaSdkLog.prefix("info for vm is null"));
                 }
             }
             return this.cachedVmSession;
@@ -152,14 +152,14 @@ private boolean isScheduling() throws AnkaMgmtException {
     }
 
     public String waitForBoot(int schedulingTimeout) throws InterruptedException, IOException, AnkaMgmtException {
-        logger.info(String.format("waiting for vm %s to boot", this.sessionId));
+        logger.info(AnkaSdkLog.prefix(String.format("waiting for vm %s to boot", this.sessionId)));
         int timeWaited = 0;
 
         while (isScheduling()) {
             // terminate if scheduling timeout is reached
             Thread.sleep(waitUnit);
             timeWaited += waitUnit;
-            logger.info(String.format("waiting for vm %s %d to stop scheduling", this.sessionId, timeWaited));
+            logger.info(AnkaSdkLog.prefix(String.format("waiting for vm %s %d to stop scheduling", this.sessionId, timeWaited)));
             if (timeWaited > schedulingTimeout * waitUnit) {
                 this.terminate();
                 throw new IOException("vm scheduling too long");
@@ -173,15 +173,15 @@ public String waitForBoot(int schedulingTimeout) throws InterruptedException, IO
             try {
                 Thread.sleep(waitUnit);
                 timeWaited += waitUnit;
-                logger.info(String.format("waiting for vm %s %d to boot", this.sessionId, timeWaited));
+                logger.info(AnkaSdkLog.prefix(String.format("waiting for vm %s %d to boot", this.sessionId, timeWaited)));
                 if (timeWaited > maxRunningTimeout) {
                     this.terminate();
                     throw new IOException("could not start vm");
 
                 }
             } catch (InterruptedException e) {
                 if (isPulling()) {  // Don't let jenkins interrupt us while we are pulling
-                    logger.info(String.format("vm %s is pulling, ignoring InterruptedException", this.sessionId));
+                    logger.info(AnkaSdkLog.prefix(String.format("vm %s is pulling, ignoring InterruptedException", this.sessionId)));
                 } else {
                     throw e;
                 }
@@ -190,7 +190,7 @@ public String waitForBoot(int schedulingTimeout) throws InterruptedException, IO
 
         String ip;
         timeWaited = 0;
-        logger.info(String.format("waiting for vm %s to get an ip ", this.sessionId));
+        logger.info(AnkaSdkLog.prefix(String.format("waiting for vm %s to get an ip ", this.sessionId)));
         while (true) { // wait to get machine ip
 
             ip = this.getIp();
@@ -199,7 +199,7 @@ public String waitForBoot(int schedulingTimeout) throws InterruptedException, IO
 
             Thread.sleep(waitUnit);
             timeWaited += waitUnit;
-            logger.info(String.format("waiting for vm %s %d to get ip ", this.sessionId, timeWaited));
+            logger.info(AnkaSdkLog.prefix(String.format("waiting for vm %s %d to get ip ", this.sessionId, timeWaited)));
             if (timeWaited > maxIpTimeout) {
                 this.terminate();
                 throw new IOException("VM started but couldn't acquire ip");

src/main/java/com/veertu/plugin/anka/AbstractAnkaSlave.java

@@ -114,11 +114,11 @@ public void terminate() throws IOException {
             Thread.sleep(3000); // Sleep for 3 seconds to avoid those spooky ChannelClosedException
             AnkaVmInstance vm = getAndLogInstance();
             if (vm != null) {
-                LOGGER.log(Level.INFO, "Node {0} Instance {1} is in state {2}", new Object[]{getNodeName(), instanceId, vm.getSessionState()});
+                LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1} is in state {2}"), new Object[]{getNodeName(), instanceId, vm.getSessionState()});
                 SaveImageParameters saveImageParams = template.getSaveImageParameters();
                 if (taskExecuted && saveImageParams != null && this.template.getSaveImageParameters().getSaveImage()
                         && saveImageParams.getSaveImage() && !hadProblemsInBuild && !hadUnknownBuildOutcome) {
-                    LOGGER.log(Level.INFO, "Node {0} Instance {1}, saving image", new Object[]{getNodeName(), instanceId});
+                    LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1}, saving image"), new Object[]{getNodeName(), instanceId});
 
                     synchronized (this) {
                         if (!this.saveImageSent) { // allow to send save image request only once
@@ -127,11 +127,11 @@ public void terminate() throws IOException {
                         }
                     }
                 } else {
-                    LOGGER.log(Level.INFO, "Node {0} Instance {1}, terminating", new Object[]{getNodeName(), instanceId});
+                    LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1}, terminating"), new Object[]{getNodeName(), instanceId});
                     cloud.terminateVMInstance(this.instanceId);
                 }
             } else {
-                LOGGER.log(Level.INFO, "Node {0} Instance {1} was not found, ensuring termination", new Object[]{getNodeName(), instanceId});
+                LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1} was not found, ensuring termination"), new Object[]{getNodeName(), instanceId});
             }
         } catch (AnkaMgmtException e) {
             throw new IOException(e);
@@ -145,9 +145,9 @@ public void terminate() throws IOException {
                     if (instance != null) {
                         state = instance.getSessionState();
                     }
-                    LOGGER.log(Level.INFO, "Node {0} Instance {1}, ensuring termination before node removal, state: {2}", new Object[]{getNodeName(), instanceId, state});
+                    LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1}, ensuring termination before node removal, state: {2}"), new Object[]{getNodeName(), instanceId, state});
                     if (instance == null || instance.isTerminatingOrTerminated()) {
-                        LOGGER.log(Level.INFO, "Node {0} Instance {1}, removing node since instance is terminated or not found", new Object[]{getNodeName(), instanceId});
+                        LOGGER.log(Level.INFO, AnkaLog.prefix("Node {0} Instance {1}, removing node since instance is terminated or not found"), new Object[]{getNodeName(), instanceId});
                         Jenkins.get().removeNode(this); // only agree to remove the node after the instance doesn't
                                                            // exist or is not started
                     }
@@ -245,12 +245,12 @@ private AnkaVmInstance getAndLogInstance() throws AnkaMgmtException {
                 String vmId = vmInfo.getUuid();
                 String hostIp = vmInfo.getHostIp();
                 String vmStatus = vmInfo.getStatus();
-                LOGGER.log(Level.FINE, "Node {0} instance {1}. instance state: {2}, " +
-                                "template id: {3}, VM uuid: {4}, VM status: {5} host IP: {6}", new Object[]{ getNodeName(), instanceId, state,
+                LOGGER.log(Level.FINE, AnkaLog.prefix("Node {0} instance {1}. instance state: {2}, " +
+                                "template id: {3}, VM uuid: {4}, VM status: {5} host IP: {6}"), new Object[]{ getNodeName(), instanceId, state,
                         templateId, vmId, vmStatus, hostIp });
             } else {
-                LOGGER.log(Level.FINE, "Node {0} instance {1}. instance state: {2}, " +
-                                "template id: {3}",  new Object[]{ getNodeName(), instanceId, state,
+                LOGGER.log(Level.FINE, AnkaLog.prefix("Node {0} instance {1}. instance state: {2}, " +
+                                "template id: {3}"),  new Object[]{ getNodeName(), instanceId, state,
                         templateId});
             }
         } else {
@@ -265,7 +265,7 @@ public boolean isAlive() {
                 AnkaVmInstance instance = getAndLogInstance();
                 if (instance != null) {
                     String state = instance.getSessionState();
-                    LOGGER.log(Level.FINE, "Anka Node {0}, instance {1} is in state {2}",
+                    LOGGER.log(Level.FINE, AnkaLog.prefix("Anka Node {0}, instance {1} is in state {2}"),
                             new Object[]{name, instanceId, state});
                     if (instance.isStarted()) {
                         return true;

src/main/java/com/veertu/plugin/anka/AnkaCloudComputer.java

@@ -175,8 +175,9 @@ void safelyCheckLatestJobAndChangeNodeBehaviour(Executor executor, Queue.Task ta
             // Unknown/unstable metadata should never prevent run-once cleanup.
             applyBuildOutcome(BuildOutcome.UNKNOWN);
             LOGGER.log(Level.WARNING,
+                    AnkaLog.prefix(
                     String.format("Computer %s, instance %s failed to resolve build result for task %s",
-                            getName(), getVMId(), task),
+                            getName(), getVMId(), task)),
                     e);
         }
     }

src/main/java/com/veertu/plugin/anka/AnkaCloudComputerListener.java

@@ -27,7 +27,7 @@ public void onLaunchFailure(Computer c, TaskListener taskListener) throws IOExce
         if (c instanceof AnkaCloudComputer) {
             AnkaCloudComputer computer = (AnkaCloudComputer)c;
             if (c.isLaunchSupported()) {
-                LOGGER.log(Level.INFO, "Computer {0}, instance {1} failed to launch, terminating",
+                LOGGER.log(Level.INFO, AnkaLog.prefix("Computer {0}, instance {1} failed to launch, terminating"),
                         new Object[]{computer.getName(), computer.getVMId()});
                 computer.terminate();
             }

src/main/java/com/veertu/plugin/anka/AnkaLog.java

@@ -0,0 +1,15 @@
+package com.veertu.plugin.anka;
+
+final class AnkaLog {
+    private static final String PREFIX = "[Anka] ";
+
+    private AnkaLog() {
+    }
+
+    static String prefix(String message) {
+        if (message == null || message.startsWith(PREFIX)) {
+            return message;
+        }
+        return PREFIX + message;
+    }
+}

src/main/java/com/veertu/plugin/anka/AnkaMgmtCloud.java

@@ -86,6 +86,7 @@ private static void InternalLog(Slave slave, SlaveComputer slaveComputer, TaskLi
         if (slave != null) s = String.format("[%s] ", slave.getNodeName());
         if (slaveComputer != null) s = String.format("[%s] ", slaveComputer.getName());
         s = s + String.format(format, args);
+        s = AnkaLog.prefix(s);
         s = s + "\n";
         if (listener != null) listener.getLogger().print(s);
         MgmtLogger.log(Level.INFO, s);
@@ -510,6 +511,8 @@ public Collection<NodeProvisioner.PlannedNode> provision(CloudState state, int e
                     if (cloudCapacity > 0) {
                         int allowedCloudCapacity = cloudCapacity - nodeCount.numNodes;
                         if (allowedCloudCapacity <= 0) {
+                            Log("Skipping provisioning for label '%s': cloud capacity reached (%d/%d active nodes)",
+                                    label, nodeCount.numNodes, cloudCapacity);
                             return plannedNodes;
                         }
                         if (number > allowedCloudCapacity) {
@@ -519,6 +522,8 @@ public Collection<NodeProvisioner.PlannedNode> provision(CloudState state, int e
                     if (t.getInstanceCapacity() > 0) {
                         int allowedTemplateCapacity = t.getInstanceCapacity() - nodeCount.numNodesPerLabel;
                         if (allowedTemplateCapacity <= 0) {
+                            Log("Skipping provisioning for label '%s': template capacity reached (%d/%d active nodes for template '%s')",
+                                    label, nodeCount.numNodesPerLabel, t.getInstanceCapacity(), t.getDisplayName());
                             return plannedNodes;
                         }
                         if (number > allowedTemplateCapacity) {
@@ -655,12 +660,19 @@ public boolean canProvision(CloudState state) {
         Label label = state.getLabel();
         AnkaCloudSlaveTemplate template = getTemplate(label);
         if (template == null) {
+            Log("Cannot provision label '%s': no matching Anka template found in cloud '%s'", label, getCloudName());
             return false;
         }
         int cloudCapacity = getCloudCapacity();
         if (template.getInstanceCapacity() > 0 || cloudCapacity >= 0) {
             NodeCountResponse countResponse = getNumOfRunningNodesPerLabel(label);
-            if ((cloudCapacity >= 0 && countResponse.numNodes >= cloudCapacity) || (template.getInstanceCapacity() > 0 && countResponse.numNodesPerLabel >= template.getInstanceCapacity())) {
+            if (cloudCapacity >= 0 && countResponse.numNodes >= cloudCapacity) {
+                Log("Cannot provision label '%s': cloud capacity reached (%d/%d active nodes)", label, countResponse.numNodes, cloudCapacity);
+                return false;
+            }
+            if (template.getInstanceCapacity() > 0 && countResponse.numNodesPerLabel >= template.getInstanceCapacity()) {
+                Log("Cannot provision label '%s': template capacity reached (%d/%d active nodes for template '%s')",
+                        label, countResponse.numNodesPerLabel, template.getInstanceCapacity(), template.getDisplayName());
                 return false;
             }
         }

src/main/java/com/veertu/plugin/anka/AnkaPlannedNodeCreator.java

@@ -7,7 +7,6 @@
 import hudson.model.Node;
 import hudson.slaves.NodeProvisioner;
 
-import java.util.concurrent.Callable;
 import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.Logger;
@@ -24,24 +23,38 @@ public class AnkaPlannedNodeCreator {
 
     public static NodeProvisioner.PlannedNode createPlannedNode(final AnkaMgmtCloud cloud, final AnkaCloudSlaveTemplate template, final AbstractAnkaSlave slave) {
         return new NodeProvisioner.PlannedNode(template.getDisplayName(),
-                Computer.threadPoolForRemoting.submit(new Callable<Node>() {
-
-
-                    public Node call() throws Exception {
+                Computer.threadPoolForRemoting.submit(() -> {
+                    try {
                         return waitAndConnect(cloud, template, slave);
+                    } catch (InterruptedException interruptedException) {
+                        terminateProvisioningInstance(cloud, slave, interruptedException);
+                        Thread.currentThread().interrupt();
+                        return null;
                     }
                 })
                 , template.getNumberOfExecutors());
     }
 
+    private static void terminateProvisioningInstance(AnkaMgmtCloud cloud, AbstractAnkaSlave slave, InterruptedException interruptedException) {
+        String instanceId = slave.getInstanceId();
+        LOGGER.log(Level.WARNING, AnkaLog.prefix("Provisioning interrupted for instance {0}, sending termination"), instanceId);
+        try {
+            cloud.terminateVMInstance(instanceId, slave);
+        } catch (AnkaMgmtException terminateError) {
+            LOGGER.log(Level.WARNING, AnkaLog.prefix("Failed to terminate interrupted instance " + instanceId), terminateError);
+        } finally {
+            LOGGER.log(Level.FINE, AnkaLog.prefix("Provisioning interruption stacktrace for instance " + instanceId), interruptedException);
+        }
+    }
+
     public static Node waitAndConnect(final AnkaMgmtCloud cloud, final AnkaCloudSlaveTemplate template, final AbstractAnkaSlave slave) throws AnkaMgmtException, InterruptedException {
         final long timeStarted = System.currentTimeMillis();
         while (true) {
             String instanceId = slave.getInstanceId();
             int vmCheckTime = cloud.getVmPollTime();
             AnkaVmInstance instance = cloud.showInstance(instanceId);
             if (instance == null) {
-                LOGGER.log(Level.WARNING, "instance `{0}` not found in cloud {1}. Terminate provisioning ",
+                LOGGER.log(Level.WARNING, AnkaLog.prefix("instance `{0}` not found in cloud {1}. Terminate provisioning "),
                         new Object[]{instanceId, cloud.getCloudName()});
                 return null;
             }
@@ -83,10 +96,10 @@ public static Node waitAndConnect(final AnkaMgmtCloud cloud, final AnkaCloudSlav
                 final long sinceStarted = System.currentTimeMillis() - timeStarted;
                 int schedulingTimeout = template.getSchedulingTimeout();
                 long schedulingTimeoutMillis = TimeUnit.SECONDS.toMillis(schedulingTimeout);
-                LOGGER.log(Level.FINE,"Instance {0} is scheduling for {1} seconds",
+                LOGGER.log(Level.FINE, AnkaLog.prefix("Instance {0} is scheduling for {1} seconds"),
                             new Object[]{instanceId, sinceStarted / 1000});
                 if (sinceStarted > schedulingTimeoutMillis) {
-                    LOGGER.log(Level.WARNING,"Instance {0} reached it's scheduling timeout of {1} seconds, terminating provisioning",
+                    LOGGER.log(Level.WARNING, AnkaLog.prefix("Instance {0} reached it's scheduling timeout of {1} seconds, terminating provisioning"),
                             new Object[]{instanceId, schedulingTimeout});
                     cloud.terminateVMInstance(instanceId);
                     return null;
@@ -96,7 +109,7 @@ public static Node waitAndConnect(final AnkaMgmtCloud cloud, final AnkaCloudSlav
             }
 
             if (instance.isTerminatingOrTerminated() || instance.isInError()) {
-                LOGGER.log(Level.WARNING,"Instance {0} is in unexpected state {1}",
+                LOGGER.log(Level.WARNING, AnkaLog.prefix("Instance {0} is in unexpected state {1}"),
                         new Object[]{instanceId, instance.getSessionState()});
                 cloud.terminateVMInstance(instanceId);
                 return null;