nightwatchjs / nightwatch

Integrated end-to-end testing framework written in Node.js and using W3C Webdriver API. Developed at @browserstack
https://nightwatchjs.org
MIT License
11.85k stars 1.35k forks source link

waitUntil may not wait when used in a custom command #3753

Open reallymello opened 1 year ago

reallymello commented 1 year ago

Description of the bug/issue

When I use waitUntil in a custom command I expect the test to waitUntil evaluates to true and exits or times out, but the test runs through it as waitUntil continues to execute sometimes even after the browser session is closed due to the test completing.

It seems to be related to what I am looping on/what commands I am using inside the body of the waitUntil. I noticed the behavior when using browser.execute, but not with other methods.

Steps to reproduce

  1. Checkout https://github.com/reallymello/nightwatchTutorials/blob/master/nw30typescriptExample/
  2. npm install followed by npx nightwatch -t "nightwatch/tests/notWaiting.ts" --headless

The test on line 14 is running dropDownPage.problemCommand(...) asserting the wrong title. "problemCommand" is a custom command that uses waitUntil to wait until the title equals the expectation. It gets the title using browser.execute inside the waitUntil body. The test is purposefully using the wrong title. For diagnostics, it is also logging the title of the page each time waitUntil loops.

You can see in the screenshot it logs the title "The Internet" twice, but then falls through to the remainder of the script and passes the test. It should have remained there and failed the test since the title will never match. The command keeps running after the browser closes causing the Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used.

image

If you comment out line 14 and uncomment the equivalent code on lines 15-21 the test will work as expected

image

image

image

Sample test

https://github.com/reallymello/nightwatchTutorials/blob/master/nw30typescriptExample/nightwatch/tests/notWaiting.ts

Command to run

npx nightwatch -t "nightwatch/tests/notWaiting.ts" --headless

Verbose Output

```sh npx nightwatch -t "nightwatch/tests/notWaiting.ts" --headless --verbose Now you can run TS tests directly using Nightwatch. [Not Waiting] Test Suite ──────────────────────────────────────────────── ⠋ Starting ChromeDriver on port 9515... Starting ChromeDriver with server_path=C:\Projects\nightwatchTutorials\nw30typescriptExample\node_modules\chromedriver\lib\chromedriver\chromedriver.exe... Request POST /session { capabilities: { firstMatch: [ {} ], alwaysMatch: { browserName: 'chrome', 'goog:chromeOptions': { args: [ 'headless=new' ] } } } ⠹ Starting ChromeDriver on port 9515... DevTools listening on ws://127.0.0.1:53397/devtools/browser/34059c69-9c52-4243-a270-f9758e0b232e ⠧ Starting ChromeDriver on port 9515... Response 200 POST /session (624ms) { value: { capabilities: { acceptInsecureCerts: false, browserName: 'chrome', browserVersion: '113.0.5672.127', chrome: { chromedriverVersion: '113.0.5672.63 (0e1a4471d5ae5bf128b1bd8f4d627c8cbd55f70c-refs/branch-heads/5672@{#912})', userDataDir: 'C:\\Users\\Mr\\AppData\\Local\\Temp\\scoped_dir21516_571968051' }, 'goog:chromeOptions': { debuggerAddress: 'localhost:53397' }, networkConnectionEnabled: false, pageLoadStrategy: 'normal', platformName: 'windows', 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:extension:minPinLength': true, 'webauthn:extension:prf': true, 'webauthn:virtualAuthenticators': true }, sessionId: 'bf4bcb60b5776bde381216d05846b6f1' } ℹ Connected to ChromeDriver on port 9515 (703ms). Using: chrome (113.0.5672.127) on WINDOWS. Received session with ID: bf4bcb60b5776bde381216d05846b6f1 → Running [before]: → Completed [before]. Running Not waiting: ─────────────────────────────────────────────────────────────────────────────────────────────────── → Running [beforeEach]: → Completed [beforeEach]. → Running [afterEach]: → Running command: url ('http://the-internet.herokuapp.com/dropdown', ) ⠋ Loading url: http://the-internet.herokuapp.com/dropdown Request POST /session/bf4bcb60b5776bde381216d05846b6f1/url ⠦ Loading url: http://the-internet.herokuapp.com/dropdown Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/url (576ms) ℹ Loaded url http://the-internet.herokuapp.com/dropdown in 578ms → Completed command: url ('http://the-internet.herokuapp.com/dropdown', ) (580ms) → Running command: waitForLoadScreen (10000) → Running command: expect.element ('#loadScreenOverlay') Request POST /session/bf4bcb60b5776bde381216d05846b6f1/elements { using: 'css selector', value: '#loadScreenOverlay' } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/elements (13ms) { value: [] } √ Expected element <#loadScreenOverlay> to not be present in 10000ms - element was not found (16ms) → Completed command: expect.element ('#loadScreenOverlay') (19ms) → Completed command: waitForLoadScreen (10000) (24ms) → Running command: expect.element ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}) Request POST /session/bf4bcb60b5776bde381216d05846b6f1/elements { using: 'css selector', value: '#dropdown' } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/elements (12ms) { value: [ { 'element-6066-11e4-a52e-4f735466cecf': '80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3' } ] } Request GET /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/property/value Response 200 GET /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/property/value (6ms) { value: '' } √ Expected element @dropDown <#dropdown> to have value equal: "" (23ms) → Completed command: expect.element ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}) (24ms) → Running command: problemCommand ('Not the title I was expecting') → Completed command: problemCommand ('Not the title I was expecting') (1ms) → Running command: waitUntil ([Function]) → Running command: execute ([Function]) Request POST /session/bf4bcb60b5776bde381216d05846b6f1/execute/sync { script: 'var passedArgs = Array.prototype.slice.call(arguments,0); return (function () {\n' + ' return document.title;\n' + ' }).apply(window, passedArgs);... (160 characters)', args: [] } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/execute/sync (7ms) { value: 'The Internet' } → Completed command: execute ([Function]) (8ms) The Internet → Running command: execute ([Function]) Request POST /session/bf4bcb60b5776bde381216d05846b6f1/execute/sync { script: 'var passedArgs = Array.prototype.slice.call(arguments,0); return (function () {\n' + ' return document.title;\n' + ' }).apply(window, passedArgs);... (160 characters)', args: [] } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/execute/sync (7ms) { value: 'The Internet' } → Completed command: execute ([Function]) (9ms) → Running command: setValue ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}, 'Option 2') The Internet Request POST /session/bf4bcb60b5776bde381216d05846b6f1/elements { using: 'css selector', value: '#dropdown' } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/elements (9ms) { value: [ { 'element-6066-11e4-a52e-4f735466cecf': '80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3' } ] } Request POST /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/clear {} Response 400 POST /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/clear (13ms) { value: { error: 'invalid element state', message: 'invalid element state\n (Session info: chrome=113.0.5672.127)', stacktrace: '' } } Request POST /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/value { text: 'Option 2', value: [ 'O', 'p', 't', 'i', 'o', 'n', ' ', '2' ] } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/value (46ms) { value: null } → Completed command: setValue ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}, 'Option 2') (77ms) → Running command: expect.element ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}) Request POST /session/bf4bcb60b5776bde381216d05846b6f1/elements { using: 'css selector', value: '#dropdown' } Response 200 POST /session/bf4bcb60b5776bde381216d05846b6f1/elements (10ms) { value: [ { 'element-6066-11e4-a52e-4f735466cecf': '80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3' } ] } Request GET /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/property/value Response 200 GET /session/bf4bcb60b5776bde381216d05846b6f1/element/80D18E3D8E6AC800FCE0BCFFCD0315A8_element_3/property/value (7ms) { value: '2' } √ Expected element @dropDown <#dropdown> to have value equal: "2" (20ms) → Completed command: expect.element ({name, __index, __selector, locateStrategy, pseudoSelector, parent, resolvedElement, abortOnFailure, suppressNotFoundErrors, timeout...}) (20ms) → Completed [afterEach]. ✨ PASSED. 3 assertions. (1.314s) → Running [after]: → Completed [after]. → Running command: end (true) → Running command: session ('delete', [Function]) Request DELETE /session/bf4bcb60b5776bde381216d05846b6f1 Response 200 DELETE /session/bf4bcb60b5776bde381216d05846b6f1 (36ms) { value: null } → Completed command: end (true) (54ms) → Completed command: session ('delete', [Function]) (40ms) Wrote HTML report file to: C:\Projects\nightwatchTutorials\nw30typescriptExample\tests_output\nightwatch-html-report\index.html Wrote JSON report file to: C:\Projects\nightwatchTutorials\nw30typescriptExample\tests_output\CHROME_113.0.5672.127__notWaiting.json Wrote XML report file to: C:\Projects\nightwatchTutorials\nw30typescriptExample\tests_output\CHROME_113.0.5672.127__notWaiting.xml → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (2ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null → Running command: execute ([Function]) Error Error while running .executeScript() protocol action: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used. → Completed command: execute ([Function]) (1ms) null Error Error while running .wait() protocol action: Wait timed out after 5263ms TimeoutError Wait timed out after 5263ms ```

Nightwatch Configuration

// Refer to the online docs for more details:
// https://nightwatchjs.org/gettingstarted/configuration/
//

//  _   _  _         _      _                     _          _
// | \ | |(_)       | |    | |                   | |        | |
// |  \| | _   __ _ | |__  | |_ __      __  __ _ | |_   ___ | |__
// | . ` || | / _` || '_ \ | __|\ \ /\ / / / _` || __| / __|| '_ \
// | |\  || || (_| || | | || |_  \ V  V / | (_| || |_ | (__ | | | |
// \_| \_/|_| \__, ||_| |_| \__|  \_/\_/   \__,_| \__| \___||_| |_|
//             __/ |
//            |___/

module.exports = {
  // An array of folders (excluding subfolders) where your tests are located;
  // if this is not specified, the test source must be passed as the second argument to the test runner.
  src_folders: ['nightwatch/tests'],

  // See https://nightwatchjs.org/guide/concepts/page-object-model.html
  page_objects_path: ['nightwatch/page-objects'],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-custom-commands.html
  custom_commands_path: ['nightwatch/commands'],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-custom-assertions.html
  custom_assertions_path: [],

  // See https://nightwatchjs.org/guide/extending-nightwatch/adding-plugins.html
  plugins: [],

  // See https://nightwatchjs.org/guide/concepts/test-globals.html
  globals_path: '',

  webdriver: {},

  test_workers: {
    enabled: true,
  },

  test_settings: {
    default: {
      disable_error_log: false,
      launch_url: 'http://localhost',

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

      desiredCapabilities: {
        browserName: 'chrome',
      },

      webdriver: {
        start_process: true,
        server_path: '',
      },
    },

    chrome: {
      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
        ],
      },
    },
  },
};

Nightwatch.js Version

3.0.0-beta.1

Node Version

18.16.0

Browser

Chrome 113

Operating System

Windows

Additional Information

Happens on 2.6.21 and the 3.0 beta. Not sure if it is related to https://github.com/nightwatchjs/nightwatch/issues/3741

reallymello commented 1 year ago

I forgot to mention I did try adding await in front of browser.waitUntil and/or the use of the command in the test and it does not help.

image

beatfactor commented 1 year ago

Ok, but if the command is async then await should be used.

reallymello commented 1 year ago

Agreed, but after going through all sorts of different iterations and not having expected behavior I started second-guessing how this command maybe was supposed to work with async await, but I guess it turned out to be this bug I'm reporting.

beatfactor commented 1 year ago

This is also related. @garg3133 has some more context.

https://github.com/nightwatchjs/nightwatch/issues/3511

garg3133 commented 1 year ago

@gravityvi This does not seem to me like a selenium issue, but an issue with Nightwatch itself. I'm saying this because I did some fresh investigations and it seems that the working of waitUntil depends on whether the command written after waitUntil is chained together with waitUntil or written separately using await.

The following code works fine (the waitUntil condition function keeps on running again and again until the function resolves to true or waitUntil times out):

it('demo waitUntil', async function () {
  browser
    .navigateTo('https://ecosia.org')
    .waitUntil(async () => {
      const title = await browser.execute(function () {
        return document.title;
      });
      console.log(title);
      return title === 'Not the title I was expecting';
    })
    .findElement('input[type=search]');
});

But in the following code, the waitUntil condition function runs only once and then the commands after waitUntil starts to execute, while the waitUntil condition function keeps on running in the background until true is returned or waitUntil is timed out.

it('demo waitUntil', async function () {
  browser
    .navigateTo('https://ecosia.org')
    .waitUntil(async () => {
      const title = await browser.execute(function () {
        return document.title;
      });
      console.log(title);
      return title === 'Not the title I was expecting';
    })

    await browser.findElement('input[type=search]');
});

I've also updated #3511 with the new findings (added a new sample code in the issue description which works fine with async/await).

garg3133 commented 1 year ago

And a workaround for @reallymello, if you chain the waitUntil in your custom-command with any random command from Nightwatch API, your test should work fine.

Below, I've chained waitUntil() with getTitle() command and it works as expected:

// nightwatch/commands/problemCommand.ts
export default class WaitForLoadScreen {
  async command(this: NightwatchClient, expectedTitle: string) {
    browser.waitUntil(async () => {
      const title = await browser.execute(function () {
        return document.title;
      });
      console.log(title);
      return title === expectedTitle;
    }).getTitle();
  }
}
reallymello commented 1 year ago

@garg3133 thanks I will try the workaround. Can you also clarify since the custom command is async if the test using it needs to call it with await or if Nightwatch handles that for me?

For example, which is correct, 1 or 2?

  1. it('demo waitUntil', async function () {
    browser.navigateTo('https://ecosia.org');
    browser.waitForLoadScreen(); // the async command inclusive of the workaround/fix
    browser.click('#something`);
    }
  2. it('demo waitUntil', async function () {
    browser.navigateTo('https://ecosia.org');
    await browser.waitForLoadScreen(); // the async command inclusive of the workaround/fix
    browser.click('#something`);
    }
beatfactor commented 1 year ago

@garg3133 Yes, I observed the same and I'm using the same workaround in the Vite plugin. It is definitely an issue with Nightwatch, but looking at the waitUntil implementation everything looks as it should be, so the only thing that must be causing this is the queuing system.

garg3133 commented 1 year ago

@reallymello No, you don't necessarily need to use await if a custom-command created by you is async, Nightwatch handles all that internally. So, both the examples provided by you are correct.

garg3133 commented 1 year ago

@beatfactor Yes, it definitely seems to be an issue with the queuing system. What happens here is that when an async callback is passed to waitUntil command, as soon as the first execution of the callback resolves, waitUntil command resolves as well with some result and the commands following the waitUntil starts to execute, while the callback to waitUntil command keeps on executing in the background until it resolves to true. But this does not happen if the next command is chained to waitUntil.

beatfactor commented 1 year ago

I wonder if we could fix this for now by wrapping the entire waitUntil command implementation in a setTimeout()? I think that would fix it until we have a better fix for the queueing system.