Report failing steps with correct duration

This fixes #963 [1].

[1] #963

Author: badeball

CHANGELOG.md

@@ -6,6 +6,8 @@ All notable changes to this project will be documented in this file.
 
 - Add BeforeStep and AfterStep hooks, fixes [#847](https://github.com/badeball/cypress-cucumber-preprocessor/issues/847).
 
+- Report failing steps with correct duration, fixes [#963](https://github.com/badeball/cypress-cucumber-preprocessor/issues/963).
+
 ## v17.1.1
 
 - Allow generation of JSON reports with hooks (After / Before) even if `baseUrl` is undefined, fixes [#1017](https://github.com/badeball/cypress-cucumber-preprocessor/issues/1017).

features/issues/963.feature

@@ -0,0 +1,28 @@
+# https://github.com/badeball/cypress-cucumber-preprocessor/issues/963
+
+Feature: message timestamps
+  Scenario: failing step
+    Given additional preprocessor configuration
+      """
+      {
+        "messages": {
+          "enabled": true
+        }
+      }
+      """
+    And a file named "cypress/e2e/a.feature" with:
+      """
+      Feature: a feature
+        Scenario: a scenario
+          Given a failing step
+      """
+    And a file named "cypress/support/step_definitions/steps.js" with:
+      """
+      const { Given } = require("@badeball/cypress-cucumber-preprocessor");
+      Given("a failing step", function() {
+        cy.wait(1000).then(() => { throw "some error" })
+      })
+      """
+    When I run cypress
+    Then it fails
+    And the message report should contain a non-zero duration of the step

features/step_definitions/messages_steps.ts

@@ -93,12 +93,21 @@ function ndJsonToString(ndjson: any) {
   return ndjson.map((o: any) => JSON.stringify(o)).join("\n") + "\n";
 }
 
-async function readMessagesReport(cwd: string): Promise<messages.Envelope[]> {
+async function readMessagesReport(
+  cwd: string,
+  options: { normalize: boolean } = { normalize: true }
+): Promise<messages.Envelope[]> {
   const absoluteMessagesPath = path.join(cwd, "cucumber-messages.ndjson");
 
   const content = await fs.readFile(absoluteMessagesPath);
 
-  return prepareMessagesReport(stringToNdJson(content.toString()));
+  const messages = stringToNdJson(content.toString());
+
+  if (options.normalize) {
+    return prepareMessagesReport(messages);
+  } else {
+    return messages;
+  }
 }
 
 function notEmpty<TValue>(value: TValue | null | undefined): value is TValue {
@@ -219,3 +228,41 @@ Then("the messages report shouldn't contain any specs", async function () {
     }
   }
 });
+
+Then(
+  "the message report should contain a non-zero duration of the step",
+  async function () {
+    const messages = await readMessagesReport(this.tmpDir, {
+      normalize: false,
+    });
+
+    type TestStepFinishedEnvelope = Pick<
+      Required<messages.Envelope>,
+      "testStepFinished"
+    >;
+
+    const isTestStepFinishedEnvelope = (
+      envelope: messages.Envelope
+    ): envelope is TestStepFinishedEnvelope => !!envelope.testStepFinished;
+
+    const testStepFinishedCol: TestStepFinishedEnvelope[] = messages.filter(
+      isTestStepFinishedEnvelope
+    );
+
+    if (testStepFinishedCol.length !== 1) {
+      throw new Error(
+        "Expected to find a single testStepFinished envelope, but found " +
+          testStepFinishedCol.length
+      );
+    }
+
+    const [{ testStepFinished }] = testStepFinishedCol;
+
+    if (
+      testStepFinished.testStepResult.duration.seconds === 0 &&
+      testStepFinished.testStepResult.duration.nanos === 0
+    ) {
+      throw new Error("Expected to find non-zero duration");
+    }
+  }
+);

lib/browser-runtime.ts

@@ -53,7 +53,7 @@ import { notNull } from "./helpers/type-guards";
 
 import { looksLikeOptions, tagToCypressOptions } from "./helpers/tag-parser";
 
-import { createTimestamp, duration } from "./helpers/messages";
+import { createTimestamp, duration, StrictTimestamp } from "./helpers/messages";
 
 import { indent, stripIndent } from "./helpers/strings";
 
@@ -97,6 +97,7 @@ interface IStep {
 export interface InternalSpecProperties {
   pickle: messages.Pickle;
   testCaseStartedId: string;
+  currentStepStartedAt?: StrictTimestamp;
   currentStep?: IStep;
   allSteps: IStep[];
   remainingSteps: IStep[];
@@ -360,6 +361,8 @@ function createPickle(context: CompositionContext, pickle: messages.Pickle) {
 
           const start = createTimestamp();
 
+          internalProperties.currentStepStartedAt = start;
+
           if (context.messagesEnabled) {
             taskTestStepStarted({
               testStepId: hook.id,
@@ -424,10 +427,11 @@ function createPickle(context: CompositionContext, pickle: messages.Pickle) {
         cy.then(() => {
           window.testState.pickleStep = step.pickleStep;
 
-          internalProperties.currentStep = { pickleStep };
-
           const start = createTimestamp();
 
+          internalProperties.currentStep = { pickleStep };
+          internalProperties.currentStepStartedAt = start;
+
           if (context.messagesEnabled) {
             taskTestStepStarted({
               testStepId: pickleStep.id,
@@ -620,7 +624,8 @@ function afterEachHandler(this: Mocha.Context, context: CompositionContext) {
 
   const properties = retrieveInternalSpecProperties();
 
-  const { testCaseStartedId, remainingSteps } = properties;
+  const { testCaseStartedId, currentStepStartedAt, remainingSteps } =
+    properties;
 
   if (context.messagesEnabled) {
     const endTimestamp = createTimestamp();
@@ -666,11 +671,13 @@ function afterEachHandler(this: Mocha.Context, context: CompositionContext) {
                 testStepResult: {
                   status: messages.TestStepResultStatus.FAILED,
                   message: this.currentTest?.err?.message,
-                  // TODO: Create a proper duration from when the step started.
-                  duration: {
-                    seconds: 0,
-                    nanos: 0,
-                  },
+                  duration: duration(
+                    assertAndReturn(
+                      currentStepStartedAt,
+                      "Expected there to be a timestamp for current step"
+                    ),
+                    endTimestamp
+                  ),
                 },
                 timestamp: endTimestamp,
               };