Possible Timing Issue with Async API Calls Within Loop

[qa-danny]

Description of the bug/issue

There appears to be an async timing issue with one of our custom functions while using Nightwatch. The custom function calls an API and compares the response with an expected response before continuing on. The failure happens when the expected response does not match, the rest of the test script appears to run while the function goes into a retry loop.

Steps to reproduce

This deals with an async/await inside of a custom function dealing with an API call.

Sample test

const fetch = require('node-fetch');

module.exports = {
  before: async function(browser) {
    browser.globals.waitForConditionTimeout = 10000;
    await browser.navigateTo('https://www.google.com/');
  },
  'API Test - GET, Expected To Pass': async function(browser) {
    // API url taken from https://jsonplaceholder.typicode.com/
    const apiUrl = 'https://jsonplaceholder.typicode.com/todos/1';
    await browser.waitForExpectedResponse(() => fetch(apiUrl),
    // expected response:
    {
      "userId": 1,
      "id": 1,
      "title": "delectus aut autem",
      "completed": false
    });
    console.log('Completed Wait For Expected Response.')
    await browser.assert.ok(true, 'Passed assertion');
    console.log('Completed Assertion, Passed.');
  },
  'API Test - GET, Forcing To Fail': async function(browser) {
    const apiUrl = 'https://dog.ceo/api/breeds/list/all';
    await browser.waitForExpectedResponse(() => fetch(apiUrl), { message: { dogBreeds: 2 }});
    console.log('Completed Wait For expected Response');
    await browser.assert.ok(true, 'Passed Assertion After Expected Failure In WFER');
  },
  after: async function(browser) {
    browser.end();
  }
}

Command to run

npx nightwatch -t e2e/test/expectedResponseTest.js

Verbose Output

⠋ Starting ChromeDriver on port 9515...
 Starting ChromeDriver with server_path=/Users/dschaich/Documents/nw_sample/node_modules/chromedriver/lib/chromedriver/chromedriver...
   Request POST /session  
   {
     capabilities: {
       firstMatch: [ {} ],
       alwaysMatch: { browserName: 'chrome', 'goog:chromeOptions': {} }
     }
⠧ Starting ChromeDriver on port 9515...
   Response 200 POST /session (1349ms)
   {
     value: {
       capabilities: {
         acceptInsecureCerts: false,
         browserName: 'chrome',
         browserVersion: '109.0.5414.87',
         chrome: {
           chromedriverVersion: '108.0.5359.71 (1e0e3868ee06e91ad636a874420e3ca3ae3756ac-refs/branch-heads/5359@{#1016})',
           userDataDir: '/var/folders/4s/vlxkxwn90md_g495k_xrx3qwl7fgpb/T/.com.google.Chrome.VDwnCL'
         },
         'goog:chromeOptions': { debuggerAddress: 'localhost:59979' },
         networkConnectionEnabled: false,
         pageLoadStrategy: 'normal',
         platformName: 'mac os x',
         proxy: {},
         setWindowRect: true,
         strictFileInteractability: false,
         timeouts: { implicit: 0, pageLoad: 300000, script: 30000 },
         unhandledPromptBehavior: 'dismiss and notify',
         'webauthn:extension:credBlob': true,
         'webauthn:extension:largeBlob': true,
         'webauthn:virtualAuthenticators': true
       },
       sessionId: '8325b068411e84208aa729f19a74b5e2'
     }
ℹ Connected to ChromeDriver on port 9515 (1414ms).
  Using: chrome (109.0.5414.87) on MAC OS X.

 Received session with ID: 8325b068411e84208aa729f19a74b5e2

Nightwatch Configuration

module.exports = {
  src_folders: ['test','nightwatch/examples'],
  page_objects_path: ['e2e/page-objects'],
  custom_commands_path: ['e2e/custom-commands'],
  custom_assertions_path: ['e2e/custom-assertions'],
  plugins: [],
  globals_path: '',
  webdriver: {},
  test_workers: {
    enabled: true
  },
  test_settings: {
    default: {
      disable_error_log: false,
      launch_url: 'https://www.zappos.com',
      screenshots: {
        enabled: false,
        path: 'screens',
        on_failure: true
      },
      desiredCapabilities: {
        browserName: 'chrome'
      },
      webdriver: {
        start_process: true,
        server_path: ''
      },
    },
    chrome: {
      desiredCapabilities: {
        browserName: 'chrome',
        'goog:chromeOptions': {
          w3c: true,
          args: [
            //'--no-sandbox',
            //'--ignore-certificate-errors',
            //'--allow-insecure-localhost',
            //'--headless'
          ]
        }
      },
      webdriver: {
        start_process: true,
        server_path: '',
        cli_args: [
          // --verbose
        ]
      }
    }
  }
}

Nightwatch.js Version

2.6.10

Node Version

16.13.1

Browser

Chrome 108

Operating System

MacOS Monterey 12.6.2

Additional Information

Screen shot of console with timestamps, highlighted line is a console.log command printing out AFTER the function that contains the loop that is still running through.

I created a dummy project for this, and it is located here: https://github.com/qa-danny/nw_test

[beatfactor]

Thanks for raising this. Btw, have you checked out our new @nightwatch/apitesting plugin which has integrated support for supertest and also a built-in mock server?

[qa-danny]

I changed the nightwatch pause function to a custom one, and it did not fail. You can see in this screenshot there are no "Completed Wait For Expected Response" and "Passed Assertion After Expected Failure In WFER" console comments in this latest test run:

[harshit-bs]

This issue seems to be caused by the pause command. We will investigate and work to resolve it promptly.

[capGoblin]

Also, another thing I noticed on debugging is that on not calling the apiMethod() and setting doesContainExpected to false it logs "Completed Wait For Expected Response" and "Passed Assertion After Expected Failure In WFER" only after the function/custom command as it is supposed to. Iam not sure why we see this behaviour if pause is the suspect

  async command(apiMethod, expectedResponse, retries = 3, timeout = 1500) {
    let response;
    let data;
    let doesContainExpected = false;
    for (; retries > 0; retries--) {
      console.log('for loop', new Date());
      try {
        // response = await apiMethod();
        console.log('completed apiMethod()', new Date());
        // data = await response.json();
      } catch (error) {
        await this.api.assert.ok(false, error);
      }
      // look through all keys in expectedResponse, and check the API response to see if they deepEqual
      // doesContainExpected = Object.keys(expectedResponse).every(key => deepEqual(expectedResponse[key], data[key]));
      console.log(`Contains Expected Response? ${doesContainExpected}`);
      if (doesContainExpected) {
        return;
      }
      console.log('pausing in function', new Date());
      await this.api.pause(timeout);
      console.log('about to repeat loop', new Date());
    }
    await this.api.assert.ok(doesContainExpected, `Exceeded max number of retries. API Response ${JSON.stringify(data)} does not contain Expected Response ${JSON.stringify(expectedResponse)}`);
  }