add startTime and endTime to step / result #2383

karate-core/src/main/java/com/intuit/karate/core/MockHandler.java

@@ -146,7 +146,7 @@ private ScenarioRuntime initRuntime(Feature feature, Map<String, Object> args) {
  return runtime;
  }
 
- private static final Result PASSED = Result.passed(0);
+ private static final Result PASSED = Result.passed(0, 0);
  private static final String ALLOWED_METHODS = "GET, HEAD, POST, PUT, DELETE, PATCH";
 
  @Override

karate-core/src/main/java/com/intuit/karate/core/Result.java

@@ -48,6 +48,9 @@ public class Result {
  private final Throwable error;
  private final boolean skipped;
  private final StepRuntime.MethodMatch matchingMethod;
+
+ private final long startTime;
+ private final long endTime;
 
  public Map<String, Object> toCucumberJson() {
  Map<String, Object> map = new HashMap(error == null ? 2 : 3);
@@ -60,9 +63,13 @@ public Map<String, Object> toCucumberJson() {
  }
 
  public static Result fromKarateJson(Map<String, Object> map) {
+ Long startTime = (Long) map.get("startTime");
+ if (startTime == null) {
+ startTime = System.currentTimeMillis();
+ }
  String status = (String) map.get("status");
  Number num = (Number) map.get("nanos");
- long durationNanos = num == null ? 0 : num.longValue();
+ long durationNanos = num == null ? 0 : num.longValue(); 
  String errorMessage = (String) map.get("errorMessage");
  Throwable error = errorMessage == null ? null : new KarateException(errorMessage);
  Boolean aborted = (Boolean) map.get("aborted");
@@ -76,14 +83,16 @@ public static Result fromKarateJson(Map<String, Object> map) {
  matchingMethod = StepRuntime.MethodMatch.getBySignatureAndArgs(jsonMatchingMethod);
  }
  }
- return new Result(status, durationNanos, error, aborted, matchingMethod);
+ return new Result(startTime, status, durationNanos, error, aborted, matchingMethod);
  }
 
  public Map<String, Object> toKarateJson() {
  Map<String, Object> map = new HashMap();
  map.put("status", status);
  map.put("millis", getDurationMillis()); // not used in fromKarateJson()
  map.put("nanos", durationNanos);
+ map.put("startTime", startTime);
+ map.put("endTime", endTime);
  if (error != null) {
  map.put("errorMessage", error.getMessage());
  }
@@ -96,9 +105,11 @@ public Map<String, Object> toKarateJson() {
  return map;
  }
 
- private Result(String status, long nanos, Throwable error, boolean aborted, StepRuntime.MethodMatch matchingMethod) {
+ private Result(long startTime, String status, long nanos, Throwable error, boolean aborted, StepRuntime.MethodMatch matchingMethod) {
+ this.startTime = startTime;
  this.status = status;
  this.durationNanos = nanos;
+ this.endTime = startTime + Math.round(ReportUtils.nanosToMillis(nanos));
  this.error = error;
  this.aborted = aborted;
  this.matchingMethod = matchingMethod;
@@ -125,18 +136,18 @@ public String getErrorMessage() {
  return error == null ? null : error.getMessage();
  }
 
- public static Result passed(long nanos) {
- return passed(nanos, null);
+ public static Result passed(long startTime, long nanos) {
+ return passed(startTime, nanos, null);
  }
- public static Result passed(long nanos, StepRuntime.MethodMatch matchingMethod) {
- return new Result(PASSED, nanos, null, false, matchingMethod);
+ public static Result passed(long startTime, long nanos, StepRuntime.MethodMatch matchingMethod) {
+ return new Result(startTime, PASSED, nanos, null, false, matchingMethod);
  }
 
- public static Result failed(long nanos, Throwable error, Step step) {
- return failed(nanos, error, step, null);
+ public static Result failed(long startTime, long nanos, Throwable error, Step step) {
+ return failed(startTime, nanos, error, step, null);
  }
 
- public static Result failed(long nanos, Throwable error, Step step, StepRuntime.MethodMatch matchingMethod) {
+ public static Result failed(long startTime, long nanos, Throwable error, Step step, StepRuntime.MethodMatch matchingMethod) {
  String message = error.getMessage();
  if (message == null) {
  message = error + ""; // make sure we show something meaningful
@@ -146,19 +157,19 @@ public static Result failed(long nanos, Throwable error, Step step, StepRuntime.
  new StackTraceElement("<feature>", ": " + step.getPrefix() + " " + step.getText() + " ", step.getDebugInfo(), step.getLine())
  };
  error.setStackTrace(newTrace);
- return new Result(FAILED, nanos, error, false, matchingMethod);
+ return new Result(startTime, FAILED, nanos, error, false, matchingMethod);
  }
 
- public static Result skipped() {
- return new Result(SKIPPED, 0, null, false, null);
+ public static Result skipped(long startTime) {
+ return new Result(startTime, SKIPPED, 0, null, false, null);
  }
 
- public static Result aborted(long nanos) {
- return aborted(nanos, null);
+ public static Result aborted(long startTime, long nanos) {
+ return aborted(startTime, nanos, null);
  }
 
- public static Result aborted(long nanos, StepRuntime.MethodMatch matchingMethod) {
- return new Result(PASSED, nanos, null, true, matchingMethod);
+ public static Result aborted(long startTime, long nanos, StepRuntime.MethodMatch matchingMethod) {
+ return new Result(startTime, PASSED, nanos, null, true, matchingMethod);
  }
 
  public String getStatus() {
@@ -173,6 +184,14 @@ public double getDurationMillis() {
  return ReportUtils.nanosToMillis(durationNanos);
  }
 
+ public long getStartTime() {
+ return startTime;
+ }
+
+ public long getEndTime() {
+ return endTime;
+ } 
+
  public StepRuntime.MethodMatch getMatchingMethod() {
  return matchingMethod;
  }

karate-core/src/main/java/com/intuit/karate/core/ScenarioResult.java

@@ -75,7 +75,7 @@ public StepResult addFakeStepResult(String message, Throwable error) {
  step.setLine(scenario.getLine());
  step.setPrefix("*");
  step.setText(message);
- Result result = error == null ? Result.passed(0) : Result.failed(0, error, step);
+ Result result = error == null ? Result.passed(System.currentTimeMillis(), 0) : Result.failed(System.currentTimeMillis(), 0, error, step);
  StepResult sr = new StepResult(step, result);
  if (error != null) {
  sr.setStepLog(error.getMessage());
@@ -107,7 +107,7 @@ private static void recurse(List<Map> list, StepResult stepResult, int depth) {
  call.setPrefix(StringUtils.repeat('>', depth));
  call.setText(fr.getCallNameForReport());
  // call.setDocString(fr.getCallArgPretty()); 
- StepResult callResult = new StepResult(call, Result.passed(0));
+ StepResult callResult = new StepResult(call, Result.passed(stepResult.getResult().getStartTime(), 0));
  callResult.setHidden(stepResult.isHidden());
  list.add(callResult.toCucumberJson());
  for (StepResult sr : fr.getAllScenarioStepResultsNotHidden()) {

karate-core/src/main/java/com/intuit/karate/core/ScenarioRuntime.java

@@ -236,7 +236,7 @@ public Result evalAsStep(String expression) {
  try {
  evalStep.parseAndUpdateFrom(expression);
  } catch (Exception e) {
- return Result.failed(0, e, evalStep);
+ return Result.failed(System.currentTimeMillis(), 0, e, evalStep);
  }
  return StepRuntime.execute(evalStep, actions);
  }
@@ -436,14 +436,14 @@ public StepResult execute(Step step) {
  final boolean executed = !stopped;
  if (stopped) {
  if (aborted && engine.getConfig().isAbortedStepsShouldPass()) {
- stepResult = Result.passed(0);
+ stepResult = Result.passed(System.currentTimeMillis(), 0);
  } else if (configFailed) {
- stepResult = Result.failed(0, error, step);
+ stepResult = Result.failed(System.currentTimeMillis(), 0, error, step);
  } else {
- stepResult = Result.skipped();
+ stepResult = Result.skipped(System.currentTimeMillis());
  }
  } else if (dryRun) {
- stepResult = Result.passed(0);
+ stepResult = Result.passed(System.currentTimeMillis(), 0);
  } else {
  stepResult = StepRuntime.execute(step, actions);
  }

karate-core/src/main/java/com/intuit/karate/core/StepResult.java

@@ -280,7 +280,7 @@ public Throwable getFailedReason() {
 
  public void setFailedReason(Throwable failedReason) {
  this.failedReason = failedReason;
- }
+ } 
 
  @Override
  public String toString() {

karate-core/src/main/java/com/intuit/karate/core/StepRuntime.java

@@ -259,10 +259,10 @@ public static Result execute(Step step, Actions actions) {
  List<MethodMatch> matches = findMethodsMatching(text);
  if (matches.isEmpty()) {
  KarateException e = new KarateException("no step-definition method match found for: " + text);
- return Result.failed(0, e, step);
+ return Result.failed(System.currentTimeMillis(), 0, e, step);
  } else if (matches.size() > 1) {
  KarateException e = new KarateException("more than one step-definition method matched: " + text + " - " + matches);
- return Result.failed(0, e, step);
+ return Result.failed(System.currentTimeMillis(), 0, e, step);
  }
  MethodMatch match = matches.get(0);
  Object last;
@@ -278,22 +278,24 @@ public static Result execute(Step step, Actions actions) {
  args = match.convertArgs(last);
  } catch (Exception ignored) { // edge case where user error causes [request =] to match [request docstring]
  KarateException e = new KarateException("no step-definition method match found for: " + text);
- return Result.failed(0, e, step);
+ return Result.failed(System.currentTimeMillis(), 0, e, step);
  }
- long startTime = System.nanoTime();
+ final long startTime = System.currentTimeMillis();
+ final long startTimeNanos = System.nanoTime();
  try {
  match.method.invoke(actions, args);
+ final long elapsedTimeNanos = getElapsedTimeNanos(startTimeNanos);
  if (actions.isAborted()) {
- return Result.aborted(getElapsedTimeNanos(startTime), match);
+ return Result.aborted(startTime, elapsedTimeNanos, match);
  } else if (actions.isFailed()) {
- return Result.failed(getElapsedTimeNanos(startTime), actions.getFailedReason(), step, match);
+ return Result.failed(startTime, elapsedTimeNanos, actions.getFailedReason(), step, match);
  } else {
- return Result.passed(getElapsedTimeNanos(startTime), match);
+ return Result.passed(startTime, elapsedTimeNanos, match);
  }
  } catch (InvocationTargetException e) {
- return Result.failed(getElapsedTimeNanos(startTime), e.getTargetException(), step, match);
+ return Result.failed(startTime, getElapsedTimeNanos(startTimeNanos), e.getTargetException(), step, match);
  } catch (Exception e) {
- return Result.failed(getElapsedTimeNanos(startTime), e, step, match);
+ return Result.failed(startTime, getElapsedTimeNanos(startTimeNanos), e, step, match);
  }
  }
 

karate-core/src/test/java/com/intuit/karate/core/feature-result.json

@@ -6,7 +6,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number"
  },
  "step": {
  "background": true,
@@ -21,7 +23,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "comments": [
@@ -39,7 +43,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 13,
@@ -56,7 +62,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 4,
@@ -70,7 +78,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 5,
@@ -90,7 +100,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 6,
@@ -132,7 +144,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 14,
@@ -165,7 +179,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "background": true,
@@ -180,7 +196,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 17,
@@ -215,7 +233,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "background": true,
@@ -230,7 +250,9 @@
  "result": {
  "nanos": "#number",
  "millis": "#number",
- "status": "passed"
+ "status": "passed",
+ "startTime": "#number",
+ "endTime": "#number" 
  },
  "step": {
  "line": 17,