Errors in custom commands hang the test (fail silently in parallel, no reports generated)

[ClaytonAstrom]

Nightwatch: 1.0.17 (reproducible in 1.0.12+)
Node: 8.12.0
OS: Mac 10.13.6
Webdriver: Chrome 2.45
Standalone Grid: 3.141.5

Looks like custom commands are hanging on failure. In parallel, the testsuite is closed and we don't even see a report of the failure. This can be a lot of missed coverage. Seems to be introduced into 1.0.12.

// test file
'use strict';
module.exports = {
  afterEach: (browser, done) => {
    browser.end(() => {
      done();
    });
  },
  'Search Test': (browser) => {
    browser.url(browser.launch_url);
    browser.searchCommand('Search');
  },
  'King Test': (browser) => {
    browser.url(browser.launch_url);
    browser.searchCommand('King');
  }
}

// searchCommand.js
exports.command = function(input) {
  this.waitForElementVisible('input[name="q"]');
  this.setValue('input[name="q"]', input);
  this.keys([this.Keys.ENTER]);
  const resultsPage = this.page.resultsPage();
  this.waitForElementVisible('.bad.selector');
  resultsPage.getResultsCount();
  resultsPage.clickFirstResult(input);
}

// resultsPage.js
'use strict';

const util = require('util');
const resultsPageCommands = {
  getResultsCount() {
    return this.api.elements('css selector', this.elements.results.selector, result => {
      console.log(result.value.length);
    });
  },
  clickFirstResult(input) {
    const selector = util.format(this.elements.resultsWithInput.selector, input);
    return this.api
      .useXpath()
      .click(selector)
      .useCss();
  }
}

module.exports = {
  commands: [resultsPageCommands],
  elements: {
    resultsWithInput: {
      locateStrategy: 'xpath',
      selector: '//*[@class="g"]//h3[contains(text(), "%s")]'
    },
    results: {
      selector: 'div#rcnt .g'
    }
  }
}

"test_settings" : {
    "default" : {
      "launch_url" : "https://www.google.com",
      "selenium_port"  : 4444,
      "selenium_host"  : "localhost",
      "silent": true,
      "end_session_on_fail": false,
      "skip_testcases_on_fail": false,
      "desiredCapabilities": {
        "browserName": "chrome",
        "marionette": true
      }
    }
  }

→ Running command: waitForElementVisible ('.bad.selector')
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (18ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (13ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (13ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (10ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (12ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (12ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (13ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (12ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (12ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (12ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
   Request POST  /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements
   { using: 'css selector', value: '.bad.selector' }
   Response 200 POST /wd/hub/session/db7b3fb091ba00cd44ff76abcef999bb/elements (13ms)
   { sessionId: 'db7b3fb091ba00cd44ff76abcef999bb',
     status: 0,
     value: [] }
✖ Timed out while waiting for element <.bad.selector> to be present for 5000 milliseconds. - expected "visible" but got: "not found"
    at NightwatchAPI.exports.command (/Users/castrom/Documents/nightwatchElements/commands/searchCommand.js:6:17)

 → Completed command waitForElementVisible ('.bad.selector') (5168ms)
^C

[ClaytonAstrom]

This seems to only happen in custom commands. If I move the logic to the test, it fails and continues

[baubie]

I am also seeing this behaviour. Could it be related to #1941?

[ClaytonAstrom]

Possibly @baubie , my only hesitation is the reported versions though. This was working in 1.0.11 and lower, where as 1941 is present in 0.9.21 as well. But it definitely looks similar

[beatfactor]

@ClaytonAstrom Thanks for reporting this. The afterEach can be simplified to:

afterEach(browser) {
  browser.end()
},

[beatfactor]

I am also seeing this behaviour. Could it be related to #1941?

It's only related in the sense that it is also affecting custom commands and their completion, but it appears to be a different problem.

In the case of #1941, the issue happens when the user doesn't emit the "complete" event (so it's more of an improvement), while in this case the completion should happen as a result of the "error" event, which is not happening.

[beatfactor]

Should be fixed in v1.0.18.

[dsesami]

I'm currently experiencing this in 1.0.19. It might be the way the callbacks are put together that prevents the parent nightwatch command from figuring out that it failed? A utility command to find and then click an element never recovers context and just hangs indefinitely.

   7 exports.command = function findThenClick (selector) {                                                                                                                                
   8     this.waitForElementPresent(selector, () => {                                                                                                                                                                
   9         this.moveToElement(selector, 0, 0, () => {                                                                                                                                                              
  10             this.click(selector, () => {                                                                                                                                                                        
  11                 this.waitForElementNotVisible('.loading');                                                                                                                                                                
  12             });                                                                                                                                                                                                 
  13         });                                                                                                                                                                                                     
  14     });                                                                                                                                                                                                         
  15     return this;                                                                                                                                                                                                
  16 };                                                                                                                                                                                                              

it gives me "timed out while waiting for element to be present" -- got "not found" (the first command, the waitForElementPresent). then it hangs.