From 30e93ed95e54d53b81a2a760a61aa1ad220cb55b Mon Sep 17 00:00:00 2001 From: Peter Thomas Date: Fri, 18 Aug 2023 15:30:54 +0530 Subject: [PATCH] add startTime and endTime to step / result #2383 --- .../com/intuit/karate/core/MockHandler.java | 2 +- .../java/com/intuit/karate/core/Result.java | 53 +++++++++++++------ .../intuit/karate/core/ScenarioResult.java | 4 +- .../intuit/karate/core/ScenarioRuntime.java | 10 ++-- .../com/intuit/karate/core/StepResult.java | 2 +- .../com/intuit/karate/core/StepRuntime.java | 20 +++---- .../intuit/karate/core/feature-result.json | 44 +++++++++++---- 7 files changed, 89 insertions(+), 46 deletions(-) diff --git a/karate-core/src/main/java/com/intuit/karate/core/MockHandler.java b/karate-core/src/main/java/com/intuit/karate/core/MockHandler.java index 2d7126bf8..a98517bfc 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/MockHandler.java +++ b/karate-core/src/main/java/com/intuit/karate/core/MockHandler.java @@ -146,7 +146,7 @@ private ScenarioRuntime initRuntime(Feature feature, Map 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 diff --git a/karate-core/src/main/java/com/intuit/karate/core/Result.java b/karate-core/src/main/java/com/intuit/karate/core/Result.java index 51c2baf8c..593bc1b20 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/Result.java +++ b/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 toCucumberJson() { Map map = new HashMap(error == null ? 2 : 3); @@ -60,9 +63,13 @@ public Map toCucumberJson() { } public static Result fromKarateJson(Map 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,7 +83,7 @@ public static Result fromKarateJson(Map 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 toKarateJson() { @@ -84,6 +91,8 @@ public Map toKarateJson() { 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 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("", ": " + 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; } diff --git a/karate-core/src/main/java/com/intuit/karate/core/ScenarioResult.java b/karate-core/src/main/java/com/intuit/karate/core/ScenarioResult.java index ffab18d88..993496caa 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/ScenarioResult.java +++ b/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 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()) { diff --git a/karate-core/src/main/java/com/intuit/karate/core/ScenarioRuntime.java b/karate-core/src/main/java/com/intuit/karate/core/ScenarioRuntime.java index 6d49006d8..1dc10e223 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/ScenarioRuntime.java +++ b/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); } diff --git a/karate-core/src/main/java/com/intuit/karate/core/StepResult.java b/karate-core/src/main/java/com/intuit/karate/core/StepResult.java index 2bd737ef2..a31b3586e 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/StepResult.java +++ b/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() { diff --git a/karate-core/src/main/java/com/intuit/karate/core/StepRuntime.java b/karate-core/src/main/java/com/intuit/karate/core/StepRuntime.java index 0db0a4ac4..bccaba0e5 100644 --- a/karate-core/src/main/java/com/intuit/karate/core/StepRuntime.java +++ b/karate-core/src/main/java/com/intuit/karate/core/StepRuntime.java @@ -259,10 +259,10 @@ public static Result execute(Step step, Actions actions) { List 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); } } diff --git a/karate-core/src/test/java/com/intuit/karate/core/feature-result.json b/karate-core/src/test/java/com/intuit/karate/core/feature-result.json index f04d81b31..863ff5cad 100644 --- a/karate-core/src/test/java/com/intuit/karate/core/feature-result.json +++ b/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,