Skip to content

Commit

Permalink
Merge pull request #44 from jenkinsci/fix-run-timing-bug-JENKINS-40162
Browse files Browse the repository at this point in the history 
Fix run timing bug for runs [JENKINS-40162]
  • Loading branch information
@svanoort
svanoort committed Jun 13, 2017
2 parents 6a302eb + 7a1ae08 commit c75efd2
Show file tree
Hide file tree
Showing 8 changed files with 101 additions and 40 deletions.
5 changes: 0 additions & 5 deletions rest-api/src/main/java/com/cloudbees/workflow/flownode/FlowNodeUtil.java
View file
Expand Up @@ -56,18 +56,13 @@
import java.util.Arrays;
import java.util.Collections;
import java.util.List;
import java.util.Set;
import java.util.concurrent.ConcurrentMap;
import java.util.logging.Level;
import java.util.logging.Logger;

/**
* @author <a href="mailto:tom.fennelly@gmail.com">tom.fennelly@gmail.com</a>
*/
public class FlowNodeUtil {

private static final Logger LOGGER = Logger.getLogger(FlowNodeUtil.class.getName());

private FlowNodeUtil() {
}

Expand Down
3 changes: 0 additions & 3 deletions rest-api/src/main/java/com/cloudbees/workflow/rest/endpoints/JobAPI.java
View file
Expand Up @@ -29,12 +29,9 @@
import com.cloudbees.workflow.util.ModelUtil;
import com.cloudbees.workflow.util.ServeJson;
import hudson.Extension;
import hudson.model.Fingerprint;
import org.jenkinsci.plugins.workflow.job.WorkflowJob;
import org.jenkinsci.plugins.workflow.job.WorkflowRun;
import org.kohsuke.stapler.QueryParameter;

import javax.annotation.CheckForNull;
import java.util.List;

/**
Expand Down
2 changes: 0 additions & 2 deletions rest-api/src/main/java/com/cloudbees/workflow/rest/endpoints/flownode/Describe.java
View file
Expand Up @@ -24,13 +24,11 @@
package com.cloudbees.workflow.rest.endpoints.flownode;

import com.cloudbees.workflow.rest.external.AtomFlowNodeExt;
import com.cloudbees.workflow.rest.external.ChunkVisitor;
import com.cloudbees.workflow.rest.external.FlowNodeExt;
import com.cloudbees.workflow.rest.external.RunExt;
import com.cloudbees.workflow.rest.external.StageNodeExt;
import com.cloudbees.workflow.rest.endpoints.FlowNodeAPI;
import hudson.model.Queue;
import org.jenkinsci.plugins.workflow.flow.FlowExecution;
import org.jenkinsci.plugins.workflow.graph.AtomNode;
import org.jenkinsci.plugins.workflow.graph.FlowNode;
import org.jenkinsci.plugins.workflow.job.WorkflowRun;
Expand Down
22 changes: 10 additions & 12 deletions rest-api/src/main/java/com/cloudbees/workflow/rest/external/RunExt.java
View file
Expand Up @@ -189,7 +189,10 @@ public void setArtifacts(Link artifacts) {

/** Computes timings after the stages have been set up
* That means timing of the stage has been computed, and the stages are sorted
*
* Deprecated but retained for external APIs consuming it, use {@link #createNew(WorkflowRun)} instead
*/
@Deprecated
public static RunExt computeTimings(RunExt runExt) {

// Pause is the sum of stage pauses
Expand Down Expand Up @@ -322,23 +325,18 @@ public static RunExt createNew(WorkflowRun run) {
long currentTimeMillis = System.currentTimeMillis();
if (runExt.getStatus() == StatusExt.IN_PROGRESS || runExt.getStatus() == StatusExt.PAUSED_PENDING_INPUT) {
runExt.setEndTimeMillis(currentTimeMillis);
} else {
runExt.setEndTimeMillis(run.getStartTimeInMillis()+run.getDuration());
}

if (runExt.getStages().isEmpty()) {
if (run.isBuilding()) { // In-progress == in queue
runExt.setQueueDurationMillis(currentTimeMillis - runExt.getStartTimeMillis());
} else {
runExt.setQueueDurationMillis(0L);
}

// Run has a timestamp when enqueued, and start time when it gets and Executor and begins running
if (run.hasntStartedYet()) {
runExt.setQueueDurationMillis(currentTimeMillis - run.getTimeInMillis()); // Enqueued time, not runtime
} else {
StageNodeExt firstExecutedStage = runExt.getFirstExecutedStage();
if (firstExecutedStage != null) {
runExt.setQueueDurationMillis(firstExecutedStage.getStartTimeMillis() - runExt.getStartTimeMillis());
}
runExt.setQueueDurationMillis(Math.max(0, run.getStartTimeInMillis()-run.getTimeInMillis()));
}

runExt.setDurationMillis(Math.max(0, runExt.getEndTimeMillis() - runExt.getStartTimeMillis() - runExt.getQueueDurationMillis()));
runExt.setDurationMillis(Math.max(0, runExt.getEndTimeMillis() - runExt.getStartTimeMillis()));

return runExt;
}
Expand Down
1 change: 0 additions & 1 deletion rest-api/src/main/java/com/cloudbees/workflow/rest/hal/Link.java
View file
Expand Up @@ -23,7 +23,6 @@
*/
package com.cloudbees.workflow.rest.hal;

import com.cloudbees.workflow.util.ModelUtil;

/**
* HAL <a href="https://tools.ietf.org/html/draft-kelly-json-hal-06#section-5">link</a>
Expand Down
1 change: 0 additions & 1 deletion rest-api/src/main/java/com/cloudbees/workflow/rest/hal/Links.java
View file
Expand Up @@ -23,7 +23,6 @@
*/
package com.cloudbees.workflow.rest.hal;

import com.cloudbees.workflow.util.ModelUtil;

/**
* Abstract HAL <a href="https://tools.ietf.org/html/draft-kelly-json-hal-06#section-4.1.1">_links</a>
Expand Down
101 changes: 88 additions & 13 deletions rest-api/src/test/java/com/cloudbees/workflow/rest/endpoints/JobAndRunAPITest.java
View file
Expand Up @@ -36,6 +36,7 @@
import com.gargoylesoftware.htmlunit.Page;
import hudson.model.Action;
import hudson.model.Result;
import hudson.model.Run;
import hudson.model.queue.QueueTaskFuture;
import org.jenkinsci.plugins.workflow.actions.TimingAction;
import org.jenkinsci.plugins.workflow.cps.CpsFlowDefinition;
Expand Down Expand Up @@ -182,6 +183,55 @@ public void testEmptyStageHandling() throws Exception {
Assert.assertTrue(first.getDurationMillis() > 0);
}

@Issue("JENKINS-40162") // Zero duration for run
@Test
public void testDuration0EdgeCase() throws Exception {
WorkflowJob job = jenkinsRule.jenkins.createProject(WorkflowJob.class, "DurationBug");

job.setDefinition(new CpsFlowDefinition("" +
"echo 'hello guys'\n" +
"stage 'one'\n" +
"node {\n" +
" sh 'sleep 5'\n" +
"}\n" +
"stage 'two'\n" +
"node {\n" +
" sh 'sleep 5'\n" +
"}\n" +
"stage 'three'\n" +
"echo 'we are going to crash....'\n" +
"throw new Exception(\"crash!!!\")\n"
));

QueueTaskFuture<WorkflowRun> build = job.scheduleBuild2(0);
jenkinsRule.assertBuildStatus(Result.FAILURE, build.get());
JenkinsRule.WebClient webClient = jenkinsRule.createWebClient();

assertBasicJobInfoOkay(job, webClient);

String jobRunsUrl = job.getUrl() + "wfapi/runs?fullStages=true";
Page runsPage = webClient.goTo(jobRunsUrl, "application/json");
String jsonResponse = runsPage.getWebResponse().getContentAsString();
JSONReadWrite jsonReadWrite = new JSONReadWrite();
RunExt[] workflowRuns = jsonReadWrite.fromString(jsonResponse, RunExt[].class);
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);

// Some extra sanity checks here just to ensure there's no deeper wackiness happening
Assert.assertEquals(3, run.getStages().size());
StageNodeExt first = run.getStages().get(0);
StageNodeExt second = run.getStages().get(1);
StageNodeExt third = run.getStages().get(1);
Assert.assertEquals(1, first.getStageFlowNodes().size());
Assert.assertEquals(1, second.getStageFlowNodes().size());
Assert.assertEquals(1, third.getStageFlowNodes().size());
assertStageInfoOkay(first, true);
assertStageInfoOkay(second, true);
assertStageInfoOkay(third, true);
Assert.assertTrue(first.getDurationMillis() > 0);
}

@Test
public void testErrorHandling() throws Exception {
WorkflowJob job = jenkinsRule.jenkins.createProject(WorkflowJob.class, "Failing Job");
Expand Down Expand Up @@ -214,6 +264,7 @@ public void testErrorHandling() throws Exception {
Assert.assertEquals(1, workflowRuns.length);
RunExt runExt = workflowRuns[0];
Assert.assertEquals(StatusExt.FAILED, runExt.getStatus());
assertRunPassesSanity(build.get(), runExt, true);
List<StageNodeExt> stages = runExt.getStages();
Assert.assertEquals(3, stages.size());

Expand Down Expand Up @@ -249,7 +300,7 @@ private void assertTimingHandlesBuggyFlowEndNode(WorkflowJob job, JenkinsRule.We
String jsonResponse = runsPage.getWebResponse().getContentAsString();
JSONReadWrite jsonReadWrite = new JSONReadWrite();
RunExt runData = jsonReadWrite.fromString(jsonResponse, RunExt.class);
assertRunInfoOkay(job, runData);
assertRunInfoOkay(job, runData, 5, 7, 9);
}

private void assertBasicJobInfoOkay(WorkflowJob job, JenkinsRule.WebClient webClient) throws IOException, SAXException {
Expand Down Expand Up @@ -281,7 +332,28 @@ private void assertBasicRunInfoOkay(WorkflowJob job, JenkinsRule.WebClient webCl
Assert.assertEquals(1, workflowRuns.length);
RunExt runExt = workflowRuns[0];

assertRunInfoOkay(job, runExt);
assertRunPassesSanity(job.getLastBuild(), runExt, false);
assertRunInfoOkay(job, runExt, 5, 7, 9);
}

private void assertRunPassesSanity(WorkflowRun myRun, RunExt runExt, boolean testStageChildren) {
long stageRunTime = 0;
long stagePauseTime = 0;
if (runExt.getStages() != null && runExt.getStages().size() > 0) {
for (StageNodeExt stage : runExt.getStages()) {
assertStageInfoOkay(stage, testStageChildren);
stageRunTime += stage.getDurationMillis();
stagePauseTime += stage.getPauseDurationMillis();
}
}
Assert.assertTrue("Run has zero duration!", runExt.getDurationMillis() > 0);
Assert.assertTrue(String.format("Run duration (%d) ms is shorter than sum of stage runtimes (%d ms), this is insane!",
runExt.getDurationMillis(), stageRunTime),
runExt.getDurationMillis() >= stageRunTime);
Assert.assertEquals(stagePauseTime, runExt.getPauseDurationMillis());
Assert.assertEquals(myRun.getId(), runExt.getId());
Assert.assertEquals(myRun.getDisplayName(), runExt.getName());
Assert.assertEquals(myRun.getStartTimeInMillis(), runExt.getStartTimeMillis());
}

private void assertDescribeEndpointOkay(WorkflowJob job, JenkinsRule.WebClient webClient) throws IOException, SAXException {
Expand All @@ -294,7 +366,7 @@ private void assertDescribeEndpointOkay(WorkflowJob job, JenkinsRule.WebClient w
JSONReadWrite jsonReadWrite = new JSONReadWrite();
RunExt workflowRun = jsonReadWrite.fromString(jsonResponse, RunExt.class);

assertRunInfoOkay(job, workflowRun);
assertRunInfoOkay(job, workflowRun, 5, 7, 9);
}

private void assertStageInfoOkay(StageNodeExt stageNodeExt, boolean mustHaveChildNodes) {
Expand Down Expand Up @@ -327,11 +399,9 @@ private void assertStageInfoOkay(StageNodeExt stageNodeExt, boolean mustHaveChil
}
}

private void assertRunInfoOkay(WorkflowJob job, RunExt runExt) {
assertRunInfoOkay(job, runExt, 5, 7, 9);
}

private void assertRunInfoOkay(WorkflowJob job, RunExt runExt, int stageid1, int stageId2, int stageId3) {
assertRunPassesSanity(job.getLastBuild(), runExt, false);

Assert.assertEquals("#1", runExt.getName());
Assert.assertEquals(StatusExt.SUCCESS, runExt.getStatus());
Assert.assertEquals("/jenkins/" + job.getUrl() + "1/wfapi/describe", runExt.get_links().self.href);
Expand Down Expand Up @@ -369,7 +439,7 @@ private void assertRunInfoOkay(WorkflowJob job, RunExt runExt, int stageid1, in
Assert.assertEquals(runExt.getStages().size(), nodes.size());
for (int i=0; i<runExt.getStages().size(); i++) {
StageNodeExt st = runExt.getStages().get(i);
assertStageInfoOkay(st, false);
// assertStageInfoOkay is called in the assertRunPassesSanity above
Assert.assertEquals(st.getId(), nodes.get(i).getId());

if (stage.getStageFlowNodes() != null) {
Expand Down Expand Up @@ -458,11 +528,12 @@ public void test_unstable_basic_flow() throws Exception {
QueueTaskFuture<WorkflowRun> build = passUnstable.scheduleBuild2(0);
jenkinsRule.assertBuildStatus(Result.UNSTABLE, build.get());
JenkinsRule.WebClient webClient = jenkinsRule.createWebClient();
RunExt[] workflowRuns = getRuns(passUnstable, webClient, "wfapi/runs/");
RunExt[] workflowRuns = getRuns(passUnstable, webClient, "wfapi/runs?fullStages=true");

// Confirm that in the case of success with overriding, all stages are marked as unstable
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);
Assert.assertEquals(StatusExt.UNSTABLE, run.getStatus());
Assert.assertEquals(3, run.getStages().size());
Assert.assertEquals(StatusExt.UNSTABLE, run.getStages().get(0).getStatus());
Expand Down Expand Up @@ -492,9 +563,10 @@ public void test_unstable_try_catch_flow() throws Exception {
JenkinsRule.WebClient webClient = jenkinsRule.createWebClient();

// Confirms that unstable & status override works with try/catch per JENKINS-34212 as well
RunExt[] workflowRuns = getRuns(failUnstable, webClient, "wfapi/runs/");
RunExt[] workflowRuns = getRuns(failUnstable, webClient, "wfapi/runs?fullStages=true");
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);
Assert.assertEquals(StatusExt.UNSTABLE, run.getStatus());
Assert.assertEquals(2, run.getStages().size());
Assert.assertEquals(StatusExt.UNSTABLE, run.getStages().get(0).getStatus());
Expand All @@ -519,9 +591,10 @@ public void test_basic_try_catch_flow() throws Exception {
JenkinsRule.WebClient webClient = jenkinsRule.createWebClient();

// Single stage should reflect final build state
RunExt[] workflowRuns = getRuns(oneStageCatch, webClient, "wfapi/runs");
RunExt[] workflowRuns = getRuns(oneStageCatch, webClient, "wfapi/runs?fullStages=true");
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);
Assert.assertEquals(StatusExt.SUCCESS, run.getStatus());
Assert.assertEquals(1, run.getStages().size());
Assert.assertEquals(StatusExt.SUCCESS, run.getStages().get(0).getStatus());
Expand All @@ -547,9 +620,10 @@ public void test_multistage_try_catch_flow() throws Exception {
JenkinsRule.WebClient webClient = jenkinsRule.createWebClient();

// Confirm that try/catch was handled: all stages should be marked successful
RunExt[] workflowRuns = getRuns(multiStageCatch, webClient, "wfapi/runs");
RunExt[] workflowRuns = getRuns(multiStageCatch, webClient, "wfapi/runs?fullStages=true");
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);
Assert.assertEquals(StatusExt.SUCCESS, run.getStatus());
Assert.assertEquals(2, run.getStages().size());
Assert.assertEquals(StatusExt.SUCCESS, run.getStages().get(0).getStatus());
Expand Down Expand Up @@ -579,11 +653,12 @@ public void test_try_catch_override_to_fail() throws Exception {
JSONReadWrite jsonReadWrite = new JSONReadWrite();

// Confirm that in the case of success with overriding, all stages are marked as unstable
String jsonResponse = webClient.goTo(job.getUrl()+"wfapi/runs/", "application/json")
String jsonResponse = webClient.goTo(job.getUrl()+"wfapi/runs?fullStages=true", "application/json")
.getWebResponse().getContentAsString();
RunExt[] workflowRuns = jsonReadWrite.fromString(jsonResponse, RunExt[].class);
Assert.assertEquals(1, workflowRuns.length);
RunExt run = workflowRuns[0];
assertRunPassesSanity(build.get(), run, true);
Assert.assertEquals(StatusExt.FAILED, run.getStatus());
Assert.assertEquals(1, run.getStages().size());
Assert.assertEquals(StatusExt.FAILED, run.getStages().get(0).getStatus());
Expand Down
6 changes: 3 additions & 3 deletions rest-api/src/test/java/com/cloudbees/workflow/rest/endpoints/UndefinedWorkflowTest.java
View file
Expand Up @@ -43,7 +43,7 @@ public class UndefinedWorkflowTest {
public JenkinsRule jenkinsRule = new JenkinsRule();

@Test
public void test_success_flow() throws Exception {
public void testUndefinedRun() throws Exception {
WorkflowJob job = jenkinsRule.jenkins.createProject(WorkflowJob.class, "Noddy Job");

// Purposely not setting a workflow definition on the job
Expand All @@ -65,8 +65,8 @@ public void test_success_flow() throws Exception {

private void assertRunOkay(RunExt workflowRun) {
Assert.assertEquals(0, workflowRun.getStages().size());
Assert.assertEquals(0L, workflowRun.getEndTimeMillis());
Assert.assertTrue("Run that should be near instant wasn't", workflowRun.getDurationMillis() < 100);
Assert.assertEquals(0L, workflowRun.getPauseDurationMillis());
Assert.assertEquals(0L, workflowRun.getQueueDurationMillis());
Assert.assertTrue("Run reports excessive queuing time", workflowRun.getQueueDurationMillis() < 100);
}
}

0 comments on commit c75efd2

Please sign in to comment.