On updating to 2.0.0-beta.1, commands no longer running in expected order

[MicahLC]

Hi,

I had been on an older version of Nightwatch with some very small modifications, basically Nightwatch v1.6.4. I'm trying to update to Nightwatch 2.0.0, and I'm on beta-1, and seeing weird behavior.

Every test starts with a custom command, setupTest, that sets the size of the window appropriately, goes to a quick-loading test URL, and sets necessary cookies. Here's what the beginning of that command looks like:

exports.command = function(params = {}) {
  /* some param processing */

  this.setWindowRect(getDeviceDimensions(device));

  this
    .url(`${testUrl}/r/health`)
    .setCookie({
      name: 'specialCookie',
      value: '1',
      domain: cookieDomain,
      path: '/'
    })
    .deleteCookie('zfc')
    .deleteCookie('zfc-dev');

Here's what the beginning of my test looks like:

module.exports = {
  'tags': [/* tags redacted */],
  '1. description of test step redacted': function(browser) {
    browser.setupTest();
    browser.goToMatchingProduct();
  },
  /* more below here, including stuff that uses data from callbacks passed to goToMatchingProduct */

On v1.6.4, here's what the beginning of the verbose output looks like, starting once the session ID is received:

15 Nov 09:48:53 Received session with ID: 7e7695a72003633e7f7b41a047b8628b

15 Nov 09:48:53 → Running [before]:
15 Nov 09:48:53 → Completed [before].
15 Nov 09:48:53 → Running [beforeEach]:
15 Nov 09:48:53 → Completed [beforeEach].
15 Nov 09:48:53
 → Running command: setupTest ()
15 Nov 09:48:53
 → Running command: resizeWindow (1440, 767)
15 Nov 09:48:53
 → Running command: windowSize ('current', 1440, 767, [Function])
15 Nov 09:48:53   Request POST  /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/window/current/size
   { width: 1440, height: 767 }
15 Nov 09:48:54   Response 200 POST /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/window/current/size (114ms)
   {
     sessionId: '7e7695a72003633e7f7b41a047b8628b',
     status: 0,
     value: null
}
15 Nov 09:48:54  → Completed command: resizeWindow (1440, 767) (118ms)
15 Nov 09:48:54  → Completed command: windowSize ('current', 1440, 767, [Function]) (116ms)
15 Nov 09:48:54
 → Running command: url ('https://www.redacted.url/r/health')
15 Nov 09:48:54   Request POST  /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/url
   { url: 'https://www.redacted.url/r/health' }
15 Nov 09:48:54   Response 200 POST /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/url (818ms)
   {
     sessionId: '7e7695a72003633e7f7b41a047b8628b',
     status: 0,
     value: null
}
15 Nov 09:48:54  → Completed command: url ('https://www.redacted.url/r/health') (820ms)
15 Nov 09:48:54
 → Running command: setCookie ({name, value, domain, path})
15 Nov 09:48:54
 → Running command: cookie ('POST', {name, value, domain, path}, [Function])
15 Nov 09:48:54   Request POST  /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/cookie
   {
     cookie: {
       name: 'specialCookie',
       value: '1',
       domain: '.redacted.url',
       path: '/'
     }
}
15 Nov 09:48:54   Response 200 POST /wd/hub/session/7e7695a72003633e7f7b41a047b8628b/cookie (10ms)
   {
     sessionId: '7e7695a72003633e7f7b41a047b8628b',
     status: 0,
     value: null
}
15 Nov 09:48:54  → Completed command: setCookie ({name, value, domain, path}) (13ms)
15 Nov 09:48:54  → Completed command: cookie ('POST', {name, value, domain, path}, [Function]) (10ms)

On 2.0.0-beta-1, here's the verbose output, starting at the same point:

15 Nov 10:07:45 Received session with ID: 58b83e8ce9d561d5a2237acb3e8340b1

15 Nov 10:07:45 → Running [before]:
15 Nov 10:07:45 → Completed [before].
15 Nov 10:07:45 → Running [beforeEach]:
15 Nov 10:07:45 → Completed [beforeEach].
15 Nov 10:07:45
 → Running command: setupTest ()
15 Nov 10:07:45
 → Running command: setWindowRect ({width, height})
15 Nov 10:07:45
 → Running command: windowRect ({width, height}, [Function])
15 Nov 10:07:45   Request POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/window/rect
   { x: undefined, y: undefined, width: 1440, height: 767 }
15 Nov 10:07:45   Response 200 POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/window/rect (133ms)
   { value: { height: 767, width: 1440, x: 22, y: 47 } }
15 Nov 10:07:45  → Completed command: setWindowRect ({width, height}) (139ms)
15 Nov 10:07:45
 → Running command: url ('https://www.redacted.url/r/health')
15 Nov 10:07:45  → Completed command: windowRect ({width, height}, [Function]) (136ms)
15 Nov 10:07:45   Request POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/url
   { url: 'https://www.redacted.url/r/health' }
15 Nov 10:07:45   Response 200 POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/url (365ms)
   { value: null }
15 Nov 10:07:45  → Completed command: url ('https://www.redacted.url/r/health') (367ms)
15 Nov 10:07:45
 → Running command: setCookie ({name, value, domain, path})
15 Nov 10:07:45
 → Running command: cookie ('POST', {name, value, domain, path}, [Function])
15 Nov 10:07:45   Request POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/cookie
   {
     cookie: {
       name: 'specialCookie',
       value: '1',
       path: '/',
       domain: '.redacted.url',
       secure: false,
       httpOnly: false,
       expiry: undefined,
       sameSite: undefined
     }
  }
15 Nov 10:07:45   Response 200 POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/cookie (7ms)
   { value: null }
15 Nov 10:07:45  → Completed command: setCookie ({name, value, domain, path}) (11ms)
15 Nov 10:07:45
 → Running command: deleteCookie ('zfc')
15 Nov 10:07:45  → Completed command: cookie ('POST', {name, value, domain, path}, [Function]) (9ms)

You can see that the order of output in the second one is different, with some commands starting before the prior command has finished (or at least logged that it has finished). This behavior continues as the test runs. There is also a point where a custom command named goToMatchingProduct that only executes a perform((client, done) => {...} command is considered to be finished right away, even though you can see the perform call finishes later:

15 Nov 10:07:46
 → Running command: goToMatchingProduct ({params})
15 Nov 10:07:46   Request POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/cookie
   {
     cookie: {
       name: 'redacted',
       value: '1',
       path: '/',
       domain: '.redacted.url',
       secure: false,
       httpOnly: false,
       expiry: undefined,
       sameSite: undefined
     }
  }
15 Nov 10:07:46
 → Running command: perform ([Function])
15 Nov 10:07:46   Response 200 POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/cookie (21ms)
   { value: null }
15 Nov 10:07:46  → Completed command: setCookie ({name, value, domain, path}) (23ms)
15 Nov 10:07:46  → Completed command: cookie ('POST', {name, value, domain, path}, [Function]) (22ms)
15 Nov 10:07:46  → Completed command: goToMatchingProduct ({params}) (22ms)
15 Nov 10:07:46 → Running [afterEach]:
15 Nov 10:07:46 → Completed [afterEach].
✔ [Test/Redacted] 1. Store product data for tests (999ms)
15 Nov 10:07:46 → Running [beforeEach]:
15 Nov 10:07:46 → Completed [beforeEach].
15 Nov 10:07:46
 → Running command: goTo ('/special.do?')
going to custom url:  https://www.redacted.url/special.do?
15 Nov 10:07:46
 → Running command: url ('https://www.redacted.url/special.do?')
15 Nov 10:07:46   Request POST /wd/hub/session/58b83e8ce9d561d5a2237acb3e8340b1/url
   { url: 'https://www.redacted.url/special.do?' }
15 Nov 10:07:47  → Completed command: perform ([Function]) (982ms)
15 Nov 10:07:47  → Completed command: goTo ('/special.do?') (914ms)

And for reference, here's what that sequence looks like on v1.6.4:

15 Nov 09:48:55  → Completed command: setupTest () (1273ms)
15 Nov 09:48:55
 → Running command: goToMatchingProduct ({params})
15 Nov 09:48:55
 → Running command: perform ([Function])
15 Nov 09:48:56  → Completed command: perform ([Function]) (882ms)
15 Nov 09:48:56  → Completed command: goToMatchingProduct ({params}) (890ms)
15 Nov 09:48:56 → Running [afterEach]:
15 Nov 09:48:56 → Completed [afterEach].
✔ [Test/Redacted] 1. Store product data for tests (2.175s)

I have made no changes to my Nightwatch settings, just browser settings (to be able to use W3C with newer versions of Chrome). Is this an expected breaking change with the new version of Nightwatch? If so, how should I be rewriting these tests and commands to work?

@beatfactor this is the issue I had mentioned seeing in #2584.

[beatfactor]

Ok, I see what's wrong. Can you share the custom commands?

[beatfactor]

I think the problem is that you're calling the done() callback before resolving the Promise. If you simply return the Promise inside the perform callback it should work.

exports.command = function(callback) {
  this.perform(function() {
    return new Promise((resolve, reject) => {
      setTimeout(function() {
        callback()
        resolve(5);
     }, 3000);
    });
  });
};

[MicahLC]

I mean, yes and no. My example is a bit contrived, so the promise there is meant as a stand-in for something real, and in the real scenario, I can't call the callback where I call resolve, because I don't control that code. Also, the perform callback is async, so it should be fine to use await for the result of the promise, pass it to callback, and then call done. Again, this is a function that worked perfectly fine in 1.6.4, but no longer works in 2.0.0. I still think this is a regression.

That said, I was able to rewrite the custom command that goToProductRepro.js is based to be a class-based command, like so:

module.exports = class goToMatchingProduct {
  async command(params) {
    // etc.
  }
}

and not use perform at all, since custom commands can be async, and also because that file only needs to make one Nightwatch call at the very end.

However, I am still seeing some of the cookie command output being out of order. I can't quite say for sure if it's having a negative impact on my test results or not.

[beatfactor]

Yeah, okay. The perform command looks like a bug indeed.

[beatfactor]

Created #2950. Feel free to add any other relevant info there.

[beatfactor]

This might have been fixed in v2.0.0-dev.12. Could you please install with npm i nightwatch@dev and try it out?