search

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.83k stars 1.32k forks source link

`done` callback in `afterEach` doesn't work when called from `.url(` callback #3643

Closed joshua-redmond closed 1 year ago

joshua-redmond commented 1 year ago

Description of the bug/issue

When a test fails, I'd like to get the final URL of the page for easier debugging.

To do this, I've registered a afterEach event that gets the URL of the browser:

afterEach:          function (browser, done) {
    browser.url(function (responseObj) {
        console.log(`Url: ${responseObj.value}`);
        done();
    });
}

The URL is gotten just fine, but then the test hangs for 2 seconds before returning this error, and skipping all remaining tests:

done() callback timeout of 20000ms was reached while executing "afterEach". Make sure to call the done() callback when the operation finishes.

It's as if done isn't getting called... except it is getting called because I still see the console.log for the URL.

This was working in v1.7.13, but stopped working since upgrading to v2.6.17.

Workaround

Interestingly, this problem goes away if you use a setInterval to poll for when the URL's been gotten:

afterEach:          function (browser, done) {
    var hasGotUrl = false;
    browser.url(function (responseObj) {
        console.log(`Url: ${responseObj.value}`);
        hasGotUrl = true;
    });
    setInterval(function () {
        if (hasGotUrl) {
            clearInterval(this);
            done();
        }
    }, 10);
}

Steps to reproduce

  1. Run: npm init nightwatch (from https://nightwatchjs.org/guide/quickstarts/create-and-run-a-nightwatch-test.html)
  2. Copy the sample test below, and paste it into: nightwatch/examples/basic/ecosia.js
  3. Run: npx nightwatch ./nightwatch/examples/basic/ecosia.js
  4. The test should fail with this error: done() callback timeout of 20000ms was reached while executing "afterEach". Make sure to call the done() callback when the operation finishes.

Sample test

module.exports = {
    'Demo test Google': function (browser) {
        browser
            .url('http://www.google.com')
            .waitForElementVisible('body', 1000)
            .setValue('input[type=text]', 'nightwatch')
            .waitForElementVisible('#elementdoesntexist', 1000)
            .end();
    },
    // BROKEN: The URL is gotten successfully, but `done` doesn't seem to be called.
    afterEach:          function (browser, done) {
        browser.url(function (responseObj) {
            console.log(`Url: ${responseObj.value}`);
            done();
        });
    }
    // WORKING: The URL is gotten successfully, and `done` is called properly.
    // afterEach:          function (browser, done) {
    //     var hasGotUrl = false;
    //     browser.url(function (responseObj) {
    //         console.log(`Url: ${responseObj.value}`);
    //         hasGotUrl = true;
    //     });
    //     setInterval(function () {
    //         if (hasGotUrl) {
    //             clearInterval(this);
    //             done();
    //         }
    //     }, 10);
    // }
};

Command to run

npx nightwatch ./nightwatch/examples/basic/ecosia.js

Verbose Output

[Basic/Ecosia] Test Suite
──────────────────────────────────────────────────
⠋ Starting ChromeDriver on port 9515...
 Starting ChromeDriver with server_path=/c/laptop/stuff/mike/junk/nightwatchtest/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 (265ms)
   {
     value: {
       capabilities: {
         acceptInsecureCerts: false,
         browserName: 'chrome',
         browserVersion: '111.0.5563.64',
         chrome: {
           chromedriverVersion: '111.0.5563.64 (c710e93d5b63b7095afe8c2c17df34408078439d-refs/branch-heads/5563@{#995})',
           userDataDir: '/tmp/.com.google.Chrome.IMszgA'
         },
         'goog:chromeOptions': { debuggerAddress: 'localhost:43543' },
         networkConnectionEnabled: false,
         pageLoadStrategy: 'normal',
         platformName: 'linux',
         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: '1a4857b93bcd63b1490fcbd2a490ff09'
     }
ℹ Connected to ChromeDriver on port 9515 (298ms).
  Using: chrome (111.0.5563.64) on LINUX.

 Received session with ID: 1a4857b93bcd63b1490fcbd2a490ff09

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

  Running Demo test Google:
──────────────────────────────────────────────────────────────────────────────────────────────────────
 → Running [beforeEach]:
 → Completed [beforeEach].

 → Running command: url ('http://www.google.com')
  ⠋ Loading url: http://www.google.com
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/url  
  ⠇ Loading url: http://www.google.com
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/url (2275ms)
  ℹ Loaded url http://www.google.com in 2278ms
  → Completed command: url ('http://www.google.com') (2280ms)

 → Running command: waitForElementVisible ('body', 1000)
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements  
   { using: 'css selector', value: 'body' }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements (15ms)
   {
     value: [
       {
         'element-6066-11e4-a52e-4f735466cecf': '10ead1c6-db19-4169-bafd-444770deb8aa'
       }
     ]
  }
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/execute/sync  
   {
     script: 'return (function(){return (function(){var k=this||self;function aa(a){return"string"==typeof a}function ba(a,b){a=a.split(".");var c=k;a[0]in c||"undefined"==typeof c.execScript||c.execScript("var "+a... (44027 characters)',
     args: [
       {
         'element-6066-11e4-a52e-4f735466cecf': '10ead1c6-db19-4169-bafd-444770deb8aa',
         ELEMENT: '10ead1c6-db19-4169-bafd-444770deb8aa'
       }
     ]
  }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/execute/sync (15ms)
   { value: true }
  ✔ Element <body> was visible after 34 milliseconds.
  → Completed command: waitForElementVisible ('body', 1000) (37ms)

 → Running command: setValue ('input[type=text]', 'nightwatch')
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements  
   { using: 'css selector', value: 'input[type=text]' }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements (8ms)
   {
     value: [
       {
         'element-6066-11e4-a52e-4f735466cecf': 'e9d228a9-e5e4-4ff1-88f7-54f89e79d8ee'
       }
     ]
  }
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/element/e9d228a9-e5e4-4ff1-88f7-54f89e79d8ee/clear  
{}
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/element/e9d228a9-e5e4-4ff1-88f7-54f89e79d8ee/clear (24ms)
   { value: null }
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/element/e9d228a9-e5e4-4ff1-88f7-54f89e79d8ee/value  
   {
     text: 'nightwatch',
     value: [
       'n', 'i', 'g', 'h',
       't', 'w', 'a', 't',
       'c', 'h'
     ]
  }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/element/e9d228a9-e5e4-4ff1-88f7-54f89e79d8ee/value (46ms)
   { value: null }
  → Completed command: setValue ('input[type=text]', 'nightwatch') (82ms)

 → Running command: waitForElementVisible ('#elementdoesntexist', 1000)
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements  
   { using: 'css selector', value: '#elementdoesntexist' }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements (10ms)
   { value: [] }
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements  
   { using: 'css selector', value: '#elementdoesntexist' }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements (26ms)
   { value: [] }
   Request POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements  
   { using: 'css selector', value: '#elementdoesntexist' }
   Response 200 POST /session/1a4857b93bcd63b1490fcbd2a490ff09/elements (26ms)
   { value: [] }
  ✖ NightwatchAssertError
   Timed out while waiting for element <#elementdoesntexist> to be present for 1000 milliseconds. - expected "visible" but got: "not found" (1070ms)

    Error location:
    /c/laptop/stuff/mike/junk/nightwatchtest/nightwatch/examples/basic/ecosia.js:
    ––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––
     5 |             .waitForElementVisible('body', 1000)
     6 |             .setValue('input[type=text]', 'nightwatch')
     7 |             .waitForElementVisible('#elementdoesntexist', 1000) 
     8 |             .end();
     9 |     },
    ––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––

  → Completed command: waitForElementVisible ('#elementdoesntexist', 1000) (1080ms)
 → Running [afterEach]:

 → Running command: url ([Function])
   Request GET /session/1a4857b93bcd63b1490fcbd2a490ff09/url  

   Response 200 GET /session/1a4857b93bcd63b1490fcbd2a490ff09/url (9ms)
   { value: 'https://www.google.com/?gws_rd=ssl' }
Url: https://www.google.com/?gws_rd=ssl
  → Completed command: url ([Function]) (11ms)
 → Running [after]:
 → Completed [after].

 → Running command: end (true)

 → Running command: session ('delete', [Function])
   Request DELETE /session/1a4857b93bcd63b1490fcbd2a490ff09  

   Response 200 DELETE /session/1a4857b93bcd63b1490fcbd2a490ff09 (52ms)
   { value: null }
  → Completed command: session ('delete', [Function]) (55ms)
 Wrote log file to: /c/laptop/stuff/mike/junk/nightwatchtest/logs/basic/ecosia_chromedriver.log
  → Completed command: end (true) (59ms)

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

  ️TEST FAILURE (24.28s): 
   - 1 error during execution; 
   - 1 assertions failed; 1 passed

   ✖ 1) basic/ecosia

   – Demo test Google 

   → ✖ NightwatchAssertError
   Timed out while waiting for element <#elementdoesntexist> to be present for 1000 milliseconds. - expected "visible" but got: "not found" (1070ms)

    Error location:
    /c/laptop/stuff/mike/junk/nightwatchtest/nightwatch/examples/basic/ecosia.js:
    ––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––
     5 |             .waitForElementVisible('body', 1000)
     6 |             .setValue('input[type=text]', 'nightwatch')
     7 |             .waitForElementVisible('#elementdoesntexist', 1000) 
     8 |             .end();
     9 |     },
    ––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––––

  - OTHER ERRORS:
  Error
    TimeoutError
   done() callback timeout of 20000ms was reached while executing "afterEach". Make sure to call the done() callback when the operation finishes.

 ChromeDriver process closed.

Nightwatch Configuration

// I've not touched this config at all.
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: ['test','nightwatch/examples'],

  // 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/custom-commands'],

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

  // 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

2.6.17

Node Version

18.15.0

Browser

Chrome 111.0.5563.64 (Official Build) (64-bit)

Operating System

Ubuntu 20.04.5 LTS

Additional Information

The same thing happens when using .execute( to get the URL instead of: .url(

gravityvi commented 1 year ago

@Mike-Wood Thanks for raising the issue.