Unexpected state in afterSpecHandler when executing over Github actions

[ccastanoAizon]

Current behavior

When executing a large test suite over Github actions using a Ubuntu Github hosted runner we are consistently reproducing an issue related with the rising of assertion errors after finishing the test execution. We have not been able to reproduce the issue when executing locally.

Scenario: List elements - Happy path # cypress/integration/e2e/ui/site/Elements/List_element.feature:4
  cypress-cucumber-preprocessor testStepStartedHandler() +41ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +14ms
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
  cypress-cucumber-preprocessor createStringAttachmentHandler() +7ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +10ms
      Given default user is logged in with Azure active directory
  cypress-cucumber-preprocessor testStepStartedHandler() +6ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +5s
      And user sets GET interceptor for "site.elements.list" endpoint with status code 200 and mock "elementsListTranslation" and query params
  cypress-cucumber-preprocessor testStepStartedHandler() +9ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +21ms
  cypress-cucumber-preprocessor testStepStartedHandler() +8ms
      And user visits "site.elements.list" page
  cypress-cucumber-preprocessor testStepFinishedHandler() +4s
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
      And user gets table content
  cypress-cucumber-preprocessor testStepFinishedHandler() +1s
      Then table contains "elemetnsListTranslation" element list mock with mapping
  cypress-cucumber-preprocessor testStepStartedHandler() +130ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +91ms
  cypress-cucumber-preprocessor testStepStartedHandler() +26ms
      (Step 6) When user sets GET interceptor for "site.elements.list" endpoint with query parameters
  cypress-cucumber-preprocessor testStepFinishedHandler() +19ms
  cypress-cucumber-preprocessor testStepStartedHandler() +41ms
      And user fills "site.inputs.search.input" input with "001"
  cypress-cucumber-preprocessor testStepFinishedHandler() +407ms
  cypress-cucumber-preprocessor testStepStartedHandler() +29ms
      (Step 8) Then request is executed
  cypress-cucumber-preprocessor testStepFinishedHandler() +44ms
  cypress-cucumber-preprocessor testStepStartedHandler() +52ms
      And user takes screenshot
  cypress-cucumber-preprocessor afterScreenshotHandler() +497ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +107ms
  cypress-cucumber-preprocessor afterScreenshotHandler() +634ms

0 passing (17s)
1 failing

List elements
"after each" hook for "List elements - Happy path":

AssertionError: expected { Object (direction, limit, ...) } to deeply equal { Object (direction, limit, ...) }

Because this error occurred during a "after each" hook we are skipping the remaining tests in the current suite: "List elements"

+ expected - actual
{ direction: "asc",
    limit: "10",
-  offset: "0",
    sortingField: "id",
-  textFilter: "001" }
+  textFilter: "" }

at eval (https://site.host.com/__cypress/tests?p=cypress/integration/e2e/ui/site/Elements/List_elements.feature:225589:37)

cypress-cucumber-preprocessor afterSpecHandler() +137ms\
An error was thrown in your plugins file while executing the handler for the after:spec event.

The error we received was:

Error: Unexpected state in afterSpecHandler: step-finished (this might be a bug, please report at https://github.com/badeball/cypress-cucumber-preprocessor)
    at createError (/home/runner/work/ui-tests/ui-tests/ui-tests/node_modules/@badeball/cypress-cucumber-preprocessor/dist/helpers/error.js:10:12)
    at afterSpecHandler (/home/runner/work/ui-tests/ui-tests/ui-tests/node_modules/@badeball/cypress-cucumber-preprocessor/dist/plugin-event-handlers.js:307:43)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Object.handler (/home/runner/work/ui-tests/ui-tests/ui-tests/node_modules/cypress-on-fix/index.js:32:20)

Step 8 (the one rising the assertion error) consist in a cy.wait of a cy.request defined in setp 6

Step 6 function:

When('user sets {requestType} interceptor for {endpoint} endpoint with query parameters', (reqType, path, stringDoc) => {
  setRequestFilters(null);
  const params = JSON.parse(stringDoc);
  cy.intercept({ pathname: CONSTANTS.getEndpoint(path), method: reqType, times: 1 }, (req) => {
    expect(req.query).to.eql(params);
  }).as('request');
});

Step 8 function:

Then('request is executed', () => {
  cy.wait('@request');
});

The error described causes an uncontrolled exception that terminates cypress run execution.

Desired behavior

When executing locally the scenario fails in a controlled way.

Scenario: List elements - Happy path # cypress/integration/e2e/ui/Elements/List_elements.feature:4
  cypress-cucumber-preprocessor testStepStartedHandler() +6ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +8ms
  cypress-cucumber-preprocessor testStepStartedHandler() +3ms
  cypress-cucumber-preprocessor createStringAttachmentHandler() +4ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +4ms
  cypress-cucumber-preprocessor testStepStartedHandler() +4ms
      Given default user is logged in with Azure active directory
  cypress-cucumber-preprocessor testStepFinishedHandler() +13s
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
      And user sets GET interceptor for "site.elements.list" endpoint with status code 200 and mock "elementsListTranslation" and query params
  cypress-cucumber-preprocessor testStepFinishedHandler() +22ms
  cypress-cucumber-preprocessor testStepStartedHandler() +2ms
      And user visits "site.elements.list" page
  cypress-cucumber-preprocessor testStepFinishedHandler() +1s
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
      And user gets table content
  cypress-cucumber-preprocessor testStepFinishedHandler() +139ms
      Then table contains "elementsListTranslation" element list mock with mapping
  cypress-cucumber-preprocessor testStepStartedHandler() +28ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +21ms
  cypress-cucumber-preprocessor testStepStartedHandler() +7ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +11ms
      And user fills "site.inputs.search.input" input with "001"
  cypress-cucumber-preprocessor testStepStartedHandler() +4ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +253ms
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
      Then request is executed
  cypress-cucumber-preprocessor afterScreenshotHandler() +629ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +11ms
      ✖ failed
        expected { Object (direction, limit, ...) } to deeply equal { Object (direction, limit, ...) }
      And user takes screenshot
  cypress-cucumber-preprocessor testStepStartedHandler() +2ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +1ms
      - skipped
  cypress-cucumber-preprocessor testCaseFinishedHandler() +2ms


  0 passing (18s)
  1 failing

  1) List elements
       List elements - Happy path:

      AssertionError: expected { Object (direction, limit, ...) } to deeply equal { Object (direction, limit, ...) }
      + expected - actual

       { direction: 'asc',
         limit: '10',
      -  offset: '0',
         sortingField: 'id',
      -  textFilter: '001' }
      +  textFilter: '' }
      
      at eval (https://site.host.com/__cypress/tests?p=cypress/integration/e2e/ui/Elements/List_Elements.feature:225438:32)

  cypress-cucumber-preprocessor afterSpecHandler() +13ms

Test code to reproduce

Unable to reproduce locally.

Versions

• Cypress version: 13.13.1
• Preprocessor version: 20.0.1
• Node version: 18.16.0

Checklist

• I've read the FAQ.
• I've read instructions for logging issues.
• I'm not using [email protected] (package name has changed and it is no longer the most recent version, see #689).

[badeball]

Hi @ccastanoAizon, thanks for reporting this. There's not really much to go on here, so I have a couple of questions for you.

using a Ubuntu Github hosted runner

Can you share your whole CI configuration / everything that pertains to the environment?

we are consistently reproducing an issue

Do you mean that this happens every time?

*pretty output*

Are you using pretty output?

When executing locally the scenario fails in a controlled way.

Let's call the local variant for "appropriate failure" and behavior seen in CI for "inappropriate failure". During a failed step, I expect to see "✖ failed" in the pretty out, as seen below.

$ cypress run

...

      Then request is executed
      ✖ failed
        expected 'bar z0mg' to equal 'bar'

Do you not see this during the inappropriate failures in CI? Or in other words - does the step appear to succeed, while the test appears to mistakenly fail in a non-existing afterEach hook?

Lastly, can you take this example-test and incorporate it into your CI system to see if it also fails? It's essentially a watered down example based on your information. Try to keep as much as your original configuration and setup, IE. only copy the index-file, the feature-file and the associated steps.

[ccastanoAizon]

Can you share your whole CI configuration / everything that pertains to the environment?

OS: Ubuntu 22.04 LTS
Runner Image:
  Image: ubuntu-22.04
  Version: 20240[7](https://github.com/aizon-execute/ui-tests/actions/runs/10171848166/job/28134318655#step:1:8)21.1.0
  Included Software: https://github.com/actions/runner-images/blob/ubuntu22/20240721.1/images/ubuntu/Ubuntu2204-Readme.md
  Image Release: https://github.com/actions/runner-images/releases/tag/ubuntu22%2F20240721.1
node-version: 18.16.0

package.json dependencies and other relevant content

"dependencies": {
    "@aizonexecute/schemas": "^1.77.0",
    "@babel/plugin-transform-modules-commonjs": "^7.22.5",
    "@babel/preset-env": "^7.22.5",
    "@babel/preset-react": "^7.22.5",
    "@babel/preset-typescript": "^7.22.5",
    "@badeball/cypress-cucumber-preprocessor": "^20.0.1",
    "@bahmutov/cypress-esbuild-preprocessor": "2.1.2",
    "@cypress/webpack-dev-server": "^3.4.1",
    "@sinonjs/fake-timers": "^11.2.2",
    "@types/node": "^20.3.1",
    "@types/react": "^18.2.29",
    "babel-loader": "^9.1.2",
    "babel-plugin-module-resolver": "^5.0.0",
    "chai": "^4.3.10",
    "chai-subset": "^1.6.0",
    "copy-webpack-plugin": "^11.0.0",
    "crypto-browserify": "^3.12.0",
    "css-loader": "^6.8.1",
    "cucumber-json-merge": "^0.0.8",
    "cucumber-junit-convert": "^2.1.1",
    "cypress": "^13.13.1",
    "cypress-downloadfile": "^1.2.3",
    "cypress-on-fix": "^1.0.2",
    "cypress-otp": "^1.0.3",
    "dayjs": "~1.11.8",
    "deepmerge": "^4.3.0",
    "dotenv": "^16.3.1",
    "esbuild-plugin-polyfill-node": "^0.3.0",
    "events": "^3.3.0",
    "i18next": "~22.4.15",
    "jsdom": "^23.2.0",
    "multiple-cucumber-html-reporter": "^3.2.0",
    "node-polyfill-webpack-plugin": "^2.0.1",
    "notistack": "~3.0.1",
    "stream": "^0.0.2",
    "typescript": "^5.3.3",
    "util-browser": "^0.0.2",
    "webpack": "^5.86.0"
  },
  "peerDependencies": {
    "react": "^18.2.0",
    "react-dom": "^18.2.0",
    "react-i18next": "12.2.2",
    "react-router-dom": "~6.11.2"
  },
  "devDependencies": {
    "@babel/eslint-parser": "^7.22.5",
    "@commitlint/cli": "^17.7.2",
    "esbuild": "0.15.18",
    "eslint": "^8.43.0",
    "eslint-config-airbnb": "~19.0.4",
    "eslint-plugin-import": "2.29.1",
    "eslint-plugin-cypress": "^2.13.3",
    "husky": "^9.0.11"
  },
 "cypress-cucumber-preprocessor": {
    "nonGlobalStepDefinitions": false,
    "json": {
      "enabled": true,
      "output": "./cypress/results/cucumber.json"
    },
    "messages": {
      "enabled": true,
      "output": "./cypress/results/cucumber-messages.ndjson"
    }
  },
  "browser": {
    "fs": false,
    "crypto": false
  }

cypress.config.ts e2e configuration and relevant data

const fillReportWithAdditionalInfo = (resultsRaw, filePath) => {
  const res = resultsRaw as any;
  const json = JSON.parse(readFileSync(filePath,"utf-8"));
  for(let i=0; i< json.length; i++) {
    json[i].metadata = {
      browser: {
        name: res.browserName,
        version: res.browserVersion
      },
      device: hostname(),
      platform: {
          name: mapOs(res.osName)
      }
    }
  }
  writeFileSync(filePath, JSON.stringify(json, null, 2));
}

const mapOs = (os) => {
  if(os.startsWith('win')) {
      return 'windows';
  } else if (os.startsWith('darwin')) {
      return 'osx';
  } else if (os.startsWith('linux')) {
      return 'linux';
  } else if (os.startsWith('ubuntu')) {
      return 'ubuntu';
  } else if (os.startsWith('android')) {
      return 'android';
  } else if (os.startsWith('ios')) {
      return 'ios';
  }
};
export default defineConfig({
  viewportWidth: 1280,
  viewportHeight: 1024,
  e2e: {
      specPattern: "cypress/integration/e2e/**/*.feature",
      experimentalModifyObstructiveThirdPartyCode: true,
      chromeWebSecurity: false,
      testIsolation: false,
      reporter: require.resolve("@badeball/cypress-cucumber-preprocessor/pretty-reporter"),
      defaultCommandTimeout: 10000,
        async setupNodeEvents(
          cypressOn: Cypress.PluginEvents,
          config: Cypress.PluginConfigOptions
        ): Promise<Cypress.PluginConfigOptions> {
          const on = require('cypress-on-fix')(cypressOn);
          await addCucumberPreprocessorPlugin(on, config, {omitAfterRunHandler: true});
          on('task', {
            downloadFile,
            generateOTP: require("cypress-otp"),
            clearDownloads(directory) {
              readdir(directory, (err, files) => {
                if (err) throw err;
                for (const file of files) {
                  unlink(join(directory, file), err => {
                    if (err) throw err;
                  });
                }
              });
              return null;
            },
            findMatchingFile({ directory, prefix }) {
              const files = readdirSync(directory);
              const matchedFile = files.find(file => file.startsWith(prefix));
              if (matchedFile) {
                return matchedFile;
              }
            },
          });
          on("file:preprocessor",
            createBundler({
              loader: {'.png': 'text'},
              plugins: [createEsbuildPlugin(config)],
            })
          );
          on('before:browser:launch', (browser, launchOptions) => {
            if (browser.name === 'chrome' && browser.isHeadless) {
              launchOptions.args.push('--window-size=1920,1080');
              launchOptions.args.push("--no-sandbox");
              launchOptions.args.push("--disable-gl-drawing-for-tests");
              launchOptions.args.push("--disable-gpu");
            }
            if (browser.name === 'electron' && browser.isHeadless) {
              launchOptions.preferences.width = 1920
              launchOptions.preferences.height = 1080
            }
            if (browser.name === 'firefox' && browser.isHeadless) {
              launchOptions.args.push('--width=1920');
              launchOptions.args.push('--height=1080');
            }
            launchOptions.args.push('--use-fake-ui-for-media-stream');
            launchOptions.args.push("--js-flags=--max-old-space-size=5500");
            launchOptions.args.push('--use-fake-device-for-media-stream');
            launchOptions.args.push('--use-file-for-fake-video-capture=cypress/fixtures/site/Elements/evidence/Webcam_sample.mjpeg');
            return launchOptions
          });
          on("after:run", async (results) => {
            if (results) {
              await afterRunHandler(config);
              try{
                fillReportWithAdditionalInfo(results,"cypress/results/cucumber.json");
              }catch(e){
                console.log(`Failed to execute after:run event: ${e}`)
              }
            }
          });
        return config;
      },
    }
});

Do you mean that this happens every time?

Yes, it happens every time in the same scenario (the one referenced above)

Are you using pretty output?

Yes.

Do you not see this during the inappropriate failures in CI? Or in other words - does the step appear to succeed, while the test appears to mistakenly fail in a non-existing afterEach hook?

I don't see it. It does appear to succeed while te test appears to mistakenly fail in an non-existing afterEach hook, yes.

Lastly, can you take this example-test and incorporate it into your CI system to see if it also fails?

We have not been able to reproduce the issue (requested scenarios was executed immediately before the failing one in the flow). Result is

 Scenario: Test scenario # cypress/integration/e2e/ui/Elements/a_list_elements.feature:4
  cypress-cucumber-preprocessor testStepStartedHandler() +8ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +21ms
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
  cypress-cucumber-preprocessor createStringAttachmentHandler() +15ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +13ms
  cypress-cucumber-preprocessor testStepStartedHandler() +7ms
      When I visit the site
  cypress-cucumber-preprocessor testStepFinishedHandler() +29ms
  cypress-cucumber-preprocessor testStepStartedHandler() +8ms
      And I intercept a POST request
  cypress-cucumber-preprocessor testStepFinishedHandler() +21ms
  cypress-cucumber-preprocessor testStepStartedHandler() +11ms
      And I press send
  cypress-cucumber-preprocessor afterScreenshotHandler() +5s
  cypress-cucumber-preprocessor testStepFinishedHandler() +16ms
      ✖ failed
        expected { Object (host, connection, ...) } to equal 'bar'
      Then the request should be fulfilled
  cypress-cucumber-preprocessor testStepStartedHandler() +5ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +10ms
      - skipped
      And user takes screenshot
  cypress-cucumber-preprocessor testStepStartedHandler() +14ms
  cypress-cucumber-preprocessor testStepFinishedHandler() +3ms
      - skipped
  cypress-cucumber-preprocessor testCaseFinishedHandler() +1ms


  0 passing (9s)
  1 failing

  1) wait for request
       Test scenario:

      AssertionError: expected { Object (host, connection, ...) } to equal 'bar'
      + expected - actual

  -{ host: "site.host.com",
      -  connection: "keep-alive",
      -  "sec-ch-ua": ""Not/A)Brand";v="8", "Chromium";v="126", "Google Chrome";v="126"",
      -  "accept-language": "en",
      -  "sec-ch-ua-mobile": "?0",
      -  "user-agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/126.0.0.0 Safari/537.36",
      -  "sec-ch-ua-platform": ""Linux"",
      -  accept: "*/*",
      -  "sec-fetch-site": "same-origin",
      -  "sec-fetch-mode": "cors",
      -  "sec-fetch-dest": "empty",
      -  referer: "https://site.host.com/login",
      -  "accept-encoding": "gzip, deflate, br, zstd",
      -  cookie: "cwr_u=4bd33335-2e44-497d-83ed-c805f6fc61f3; cwr_s=eyJzZXNzaW9uS" }
      +"bar"
      
      at eval (https://site.host.com/__cypress/tests?p=cypress/integration/e2e/ui/manager/Elements/a_list_element.feature:16029:34)

[badeball]

await afterRunHandler(config);

Therein may lie your issue. You're combining two workarounds. Either you invoke afterRunHandler yourself, or you use cypress-on-fix.

[ccastanoAizon]

Therein may lie your issue. You're combining two workarounds. Either you invoke afterRunHandler yourself, or you use cypress-on-fix.

Seems like removing the afterRunHandler wait fixed the issue. Thanks.