`perform` with `done` callback doesn't stop timeout timer in case of error

[ruzv]

perform with callback doesn't stop timeout timer in case of error

If an error occurs while executing perform's callback function then the error is reported, but the timeout timer is not stopped and the test hangs until the time out is reached.

Expected result: timeout timer is stopped and test execution is stopped

Sample test

sampleTest.js

module.exports = {
    Test: (client) => {
        console.log("testing");
        client.perform((done) => {
            client
                .click("does not exist")
                .perform(done);
        });
    },
};

Run with command

$ npx nightwatch

Verbose output

debug.log

[First] Test Suite
────────────────────────────────────
⠋ Starting ChromeDriver on port 9515...
 Starting ChromeDriver with server_path=/Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/node_modules/chromedriver/lib/chromedriver/chromedriver...
   Request POST /session  
   {
     desiredCapabilities: {
       browserName: 'chrome',
       'goog:chromeOptions': { w3c: true, args: [] },
       name: 'First'
     },
     capabilities: {
       alwaysMatch: {
         browserName: 'chrome',
         'goog:chromeOptions': { w3c: true, args: [] }
       }
     }
⠴ Starting ChromeDriver on port 9515...
   Response 200 POST /session (1260ms)
   {
     value: {
       capabilities: {
         acceptInsecureCerts: false,
         browserName: 'chrome',
         browserVersion: '103.0.5060.53',
         chrome: {
           chromedriverVersion: '103.0.5060.53 (a1711811edd74ff1cf2150f36ffa3b0dae40b17f-refs/branch-heads/5060@{#853})',
           userDataDir: '/var/folders/65/207sntgd6rjcr3bxl5zctw9m0000gn/T/.com.google.Chrome.uBGxsu'
         },
         'goog:chromeOptions': { debuggerAddress: 'localhost:61865' },
         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: '49c4df80388886749b4095e81249c63d'
     }
ℹ Connected to ChromeDriver on port 9515 (1322ms).
  Using: chrome (103.0.5060.53) on MAC OS X.

 Received session with ID: 49c4df80388886749b4095e81249c63d

 → Running [before]:
 → Completed [before].



  Running Test:
───────────────────────────────────────────────────────────────────────────────────────────────────
 → Running [beforeEach]:
 → Completed [beforeEach].
testing
 
 → Running command: perform ([Function])
 
 → Running command: click ('does not exist')
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (17ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (14ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (12ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (9ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (13ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (13ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (14ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (14ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (14ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (12ms)
   { value: [] }
   Request POST /session/49c4df80388886749b4095e81249c63d/elements  
   { using: 'css selector', value: 'does not exist' }
   Response 200 POST /session/49c4df80388886749b4095e81249c63d/elements (13ms)
   { value: [] }
  NoSuchElementError: An error occurred while running .click() command on <does not exist>: Timed out while waiting for element "does not exist" with "css selector" to be present for 5000 milliseconds.
       at NightwatchAPI.<anonymous> (/Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/tests/src/tests/first.js:6:14)
  → Completed command: click ('does not exist') (5175ms)
 
 → Running command: perform ([Function])
  → Completed command: perform ([Function]) (5179ms)
  → Completed command: perform ([Function]) (10002ms)
 → Running [afterEach]:
 → Completed [afterEach].

FAILED: 2 errors (15.187s)
  Error: Error while running "perform" command: Timeout while waiting (10000ms) for the .perform() command callback to be called.
       at NightwatchAPI.<anonymous> (/Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/tests/src/tests/first.js:6:38)
 → Running [after]:
 → Completed [after].
 
 → Running command: end ()
 
 → Running command: session ('delete', [Function])
   Request DELETE /session/49c4df80388886749b4095e81249c63d  

   Response 200 DELETE /session/49c4df80388886749b4095e81249c63d (64ms)
   { value: null }
  → Completed command: session ('delete', [Function]) (70ms)
 Wrote log file to: /Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/logs/first_chromedriver.log.
  → Completed command: end () (78ms)

────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────

  TEST FAILURE (16.734s): 
   - 2 errors during execution; 
   - 0 tests failed; 
   - 0/1 tests passed



 NoSuchElementError: An error occurred while running .click() command on <does not exist>: Timed out while waiting for element "does not exist" with "css selector" to be present for 5000 milliseconds.
       at NightwatchAPI.<anonymous> (/Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/tests/src/tests/first.js:6:14)


 Error: Error while running "perform" command: Timeout while waiting (10000ms) for the .perform() command callback to be called.
       at NightwatchAPI.<anonymous> (/Users/user/go/src/code.tdlbox.com/loadero/test-script-runners/nw2/tests/src/tests/first.js:6:38)

 ✖ 1) first
 – Test (15.187s)

 ChromeDriver process closed.

Configuration

nightwatch.json

module.exports = {
  src_folders: ["./tests/src/tests"],

  page_objects_path: ["node_modules/nightwatch/examples/pages/"],

  custom_commands_path: ["tests/src/commands"],

  custom_assertions_path: "",

  plugins: [],

  globals_path: "",

  webdriver: {},

  test_settings: {
    default: {
      disable_error_log: false,
      launch_url: "https://nightwatchjs.org",

      screenshots: {
        enabled: false,
        path: "screens",
        on_failure: true,
      },

      globals: {
        asyncHookTimeout: 10000,
      },

      desiredCapabilities: {
        browserName: "chrome",
        "goog:chromeOptions": {
          // More info on Chromedriver: https://sites.google.com/a/chromium.org/chromedriver/
          //
          // w3c:false tells Chromedriver to run using the legacy JSONWire protocol (not required in Chrome 78)
          w3c: true,
          args: [
            //'--no-sandbox',
            //'--ignore-certificate-errors',
            //'--allow-insecure-localhost',
            //'--headless'
          ],
        },
      },

      webdriver: {
        start_process: true,
        server_path: "",
        cli_args: [
          // --verbose
        ],
      },
    },
  },
};

Your Environment

Executable	Version
nightwatch --version	2.2.2
npm --version	8.5.3
yarn --version	n/a
node --version	v14.17.0

Browser driver	Version
chromedriver	103.0.5060.53

OS	Version
macOS Monterey	12.4

[ruzv]

the cause for this is that in NW2 perform done callback is a single argument function, then passing it to another perform generates a new done callback that is never called, soo making the test hang.

[ruzv]

Another issue with perform similar to this one present in NW 1.7 and 2 is that when perform wraps a custom command and the custom command throws or emits an error the test hangs until perform's timeout is reached. The expected behavior would be that in case of error the timeout is cleared.

I've looked at perform's source code and it seems to have handled for cases like this, but for custom commands, it just does not work.

//sample custom command
class CustomCommandWithError extends EventEmitter {
    command() {
        self.emit("error", new Error("error"));
        // throw new Error("error"); has the same effect
    }
}

// sample test
client.perform((done) => {
    client.customCommandWithError()
        .perform(() => { // .perform(done) does not work in NW2 for the reasons mentioned in comment above
            done();
         });
});

[swrdfish]

In the first test case, you have to call the done command in a different way:

module.exports = {
  Test: (client) => {
    // eslint-disable-next-line no-console
    console.log('testing');
    client.perform((done) => {
      const doneFirst = done;
      client
        .click('does not exist')
        .perform((done) => {
          doneFirst();
          done();
        });
    });
  }
};

[gravityvi]

@ruzv Can you let us know what's the use case you are trying to achieve by using custom commands inside perform?

[ruzv]

We have a custom command waitForDownloadFinnish(filename, timeout) that runs a custom binary that will check the filesystem for a specified filename. It will fail if the filename did not appear in the filesystem in the specified timeout.

If you have a test script that uses some kind of a variable

module.exports = {
  Test: (client) => {
    let filename = "bananas"; // default value

    client
      .getText(".filename", (result) => {
        // get the name of the file about to be downloaded
        filename = result.value;
      })
      .click(".filename") // start the download
      // will wait for file "bananas" to get downloaded
      .waitForDownloadFinnish(filename, 10 * 1000);
    // likely "bananas" is not the actual file name from getText command
    // hence the waitForDownloadFinnish command will fail
  },
};

then waitForDownloadFinnish command will get enqueued before getText and click finish execution and will have a wrong filename value ("bananas"). A way around this is to use perform

module.exports = {
  Test: (client) => {
    let filename = "bananas"; // default value

    client
      .getText(".filename", (result) => {
        // get the name of the file about to be downloaded
        filename = result.value;
      })
      .click(".filename") // start the download
      .perform((done) => {
        client.waitForDownloadFinnish(filename, 10 * 1000).perform(() => {
          done();
        });
      });
  },
};

Now the waitForDownloadFinnish command will get enqueued only when perform starts execution. This ensures that it will have the correct value retrieved from getText instead of the default one.

[AutomatedTester]

This might be related to #3351

[AutomatedTester]

@swrdfish can you check if this is now fixed?