[JENKINS-30269] Better logs when using the lock step

jenkinsci · Mar 11, 2016 · aea4806 · aea4806
1 parent 810e1e9
commit aea4806
Show file tree

Hide file tree

Showing 4 changed files with 88 additions and 20 deletions.
diff --git a/src/main/java/org/jenkins/plugins/lockableresources/LockStepExecution.java b/src/main/java/org/jenkins/plugins/lockableresources/LockStepExecution.java
@@ -1,9 +1,9 @@
 package org.jenkins.plugins.lockableresources;
 
-import java.util.Arrays;
 import java.util.UUID;
 import java.util.concurrent.ScheduledFuture;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Logger;
 
 import javax.annotation.Nonnull;
 
@@ -36,10 +36,16 @@ public class LockStepExecution extends AbstractStepExecutionImpl {
 	private transient volatile ScheduledFuture<?> task;
 	private BodyExecution body;
 	private final String id = UUID.randomUUID().toString();
+	private static final Logger LOGGER = Logger.getLogger(LockStepExecution.class.getName());
 
 	@Override
 	public boolean start() throws Exception {
-		tryLock(0);
+		listener.getLogger().println("Trying to acquire lock on [" + step.resource + "]");
+		if (!lockAndProceed()) {
+			listener.getLogger().println(new LockableResourcesStruct(step.resource).required.get(0).getLockCause());
+			listener.getLogger().println("Waiting for lock...");
+			tryLock(0);
+		}
 		return false;
 	}
 
@@ -57,15 +63,17 @@ public void run() {
 
 	private boolean lockAndProceed() {
 		LockableResourcesStruct resourceHolder = new LockableResourcesStruct(step.resource);
+		LOGGER.finest("Trying to acquire [" + step.resource + "]");
 		if (LockableResourcesManager.get().lock(resourceHolder.required, run)) {
-			LockableResourcesManager.get().save(); // save state
-			listener.getLogger().println("Lock aquired on [" + step.resource + "]");
+			listener.getLogger().println("Lock acquired on [" + step.resource + "]");
+			LOGGER.finest("Lock acquired on [" + step.resource + "]");
 			body = getContext().newBodyInvoker().
 				withCallback(new Callback(resourceHolder, run)).
 				withDisplayName(null).
 				start();
 			return true;
 		} else {
+			resourceHolder.required.get(0).getLockCause();
 			return false;
 		}
 	}
@@ -90,27 +98,36 @@ private static final class Callback extends BodyExecutionCallback {
 		private final String buildExternalizableId;
 
 		Callback(LockableResourcesStruct resourceHolder, Run<?, ?> run) {
+			// It's granted to contain one item (and only one for now)
 			this.resourceHolder = resourceHolder;
 			this.run = run;
 			this.buildExternalizableId = run.getExternalizableId();
 		}
 
 		@Override
 		public void onSuccess(StepContext context, Object result) {
-			if (run == null && buildExternalizableId != null) {
-				run = Run.fromExternalizableId(buildExternalizableId);
-			}
-			LockableResourcesManager.get().unlock(resourceHolder.required, run);
+			unlock(context);
 			context.onSuccess(result);
 		}
 
 		@Override
 		public void onFailure(StepContext context, Throwable t) {
+			unlock(context);
+			context.onFailure(t);
+		}
+
+		private void unlock(StepContext context) {
 			if (run == null && buildExternalizableId != null) {
 				run = Run.fromExternalizableId(buildExternalizableId);
 			}
 			LockableResourcesManager.get().unlock(resourceHolder.required, run);
-			context.onFailure(t);
+			try {
+				// It's granted to contain one (and only one for now)
+				context.get(TaskListener.class).getLogger().println("Lock released on resouce [" + resourceHolder.required.get(0) + "]");
+				LOGGER.finest("Lock released on [" + resourceHolder.required.get(0) + "]");
+			} catch (Exception e) {
+				context.onFailure(e);
+			}
 		}
 
 		private static final long serialVersionUID = 1L;

diff --git a/src/main/java/org/jenkins/plugins/lockableresources/LockableResource.java b/src/main/java/org/jenkins/plugins/lockableresources/LockableResource.java
@@ -38,6 +38,8 @@
 
 import com.infradna.tool.bridge_method_injector.WithBridgeMethods;
 
+import edu.umd.cs.findbugs.annotations.CheckForNull;
+
 @ExportedBean(defaultVisibility = 999)
 public class LockableResource extends AbstractDescribableImpl<LockableResource> implements Serializable {
 
@@ -51,7 +53,7 @@ public class LockableResource extends AbstractDescribableImpl<LockableResource>
 	private String labels = "";
 	private String reservedBy = null;
 
-	private int queueItemId = NOT_QUEUED;
+	private long queueItemId = NOT_QUEUED;
 	private String queueItemProject = null;
 	private transient Run<?, ?> build = null;
 	// Needed to make the state non-transient
@@ -164,12 +166,12 @@ public boolean isQueued() {
 	}
 
 	// returns True if queued by any other task than the given one
-	public boolean isQueued(int taskId) {
+	public boolean isQueued(long taskId) {
 		this.validateQueuingTimeout();
 		return queueItemId != NOT_QUEUED && queueItemId != taskId;
 	}
 
-	public boolean isQueuedByTask(int taskId) {
+	public boolean isQueuedByTask(long taskId) {
 		this.validateQueuingTimeout();
 		return queueItemId == taskId;
 	}
@@ -182,7 +184,23 @@ public void unqueue() {
 
 	@Exported
 	public boolean isLocked() {
-		return build != null;
+		return getBuild() != null;
+	}
+
+	/**
+	 * Resolve the lock cause for this resource. It can be reserved or locked.
+	 *
+	 * @return the lock cause or null if not locked
+	 */
+	@CheckForNull
+	public String getLockCause() {
+		if (isReserved()) {
+			return String.format("[%s] is reserved by %s", name, reservedBy);
+		}
+		if (isLocked()) {
+			return String.format("[%s] is locked by %s", name, buildExternalizableId);
+		}
+		return null;
 	}
 
 	@WithBridgeMethods(value=AbstractBuild.class, adapterMethod="getAbstractBuild")
@@ -203,8 +221,8 @@ private Object getAbstractBuild(final Run owner, final Class targetClass) {
 
 	@Exported
 	public String getBuildName() {
-		if (build != null)
-			return build.getFullDisplayName();
+		if (getBuild() != null)
+			return getBuild().getFullDisplayName();
 		else
 			return null;
 	}
@@ -227,7 +245,7 @@ public Task getTask() {
 		}
 	}
 
-	public int getQueueItemId() {
+	public long getQueueItemId() {
 		this.validateQueuingTimeout();
 		return queueItemId;
 	}
@@ -237,12 +255,12 @@ public String getQueueItemProject() {
 		return this.queueItemProject;
 	}
 
-	public void setQueued(int queueItemId) {
+	public void setQueued(long queueItemId) {
 		this.queueItemId = queueItemId;
 		this.queuingStarted = System.currentTimeMillis() / 1000;
 	}
 
-	public void setQueued(int queueItemId, String queueProjectName) {
+	public void setQueued(long queueItemId, String queueProjectName) {
 		this.setQueued(queueItemId);
 		this.queueItemProject = queueProjectName;
 	}

diff --git a/src/test/java/org/jenkins/plugins/lockableresources/LockStepTest.java b/src/test/java/org/jenkins/plugins/lockableresources/LockStepTest.java
@@ -0,0 +1,33 @@
+package org.jenkins.plugins.lockableresources;
+
+
+import org.jenkinsci.plugins.workflow.cps.CpsFlowDefinition;
+import org.jenkinsci.plugins.workflow.job.WorkflowJob;
+import org.jenkinsci.plugins.workflow.job.WorkflowRun;
+import org.junit.Rule;
+import org.junit.runners.model.Statement;
+import org.jvnet.hudson.test.RestartableJenkinsRule;
+
+public class LockStepTest {
+
+	@Rule
+	public RestartableJenkinsRule story = new RestartableJenkinsRule();
+
+	public void lockOrder() {
+		story.addStep(new Statement() {
+			@Override
+			public void evaluate() throws Throwable {
+				WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "p");
+				p.setDefinition(new CpsFlowDefinition(
+						"echo 'Start'\n" +
+						"lock('resource1') {\n" +
+						"	semaphore 'wait'\n" +
+						"}\n" +
+						"echo 'Finish'"
+				));
+				WorkflowRun b1 = p.scheduleBuild2(0).waitForStart();
+			}
+		});
+	}
+
+}
diff --git a/src/test/java/org/jenkins/plugins/lockableresources/LockableResourceTest.java b/src/test/java/org/jenkins/plugins/lockableresources/LockableResourceTest.java
@@ -200,8 +200,8 @@ public void testSetBuild() {
 	@Test
 	public void testGetQueueItemId() {
 		System.out.println("getQueueItemId");
-		int expResult = 0;
-		int result = instance.getQueueItemId();
+		long expResult = 0;
+		long result = instance.getQueueItemId();
 		assertEquals(expResult, result);
 	}