Codeceptjs: extreme slowness: uses 45 seconds to fill one form

[fatso83]

What are you trying to achieve?

Fill _one_ page with a form in a reasonable amount of time.

What do you get instead?

The form filling proceeds _extremely_ slowly. Filling the form takes about 45-50 seconds. The test that fills out input fields pauses for 5-10 seconds between each field, and then suddenly speeds up for the last few fields. See this video.

Needless to say, this page works quickly/fast when filling the page using my keyboard.

I suspect that it is somehow related to Javascript (perhaps onchange validation triggers), since the login page fillout (no validation) goes quickly until the click handler is touched, but as the script runs in the fast Chrome engine it shouldn't matter. When running the login procedure that fills in username and password it proceeds quickly (except for a long delay after clicking the login button).

Another hint it might have something to do with JS is observing the output when running with --steps, as you can see the time does not change between the filling out steps, even though it in practice actually takes 5-10 seconds between each step. It is if everything is one big blocking operation. Then it is like running executeScript changes this, as time jumps from 13:35:20 to 13:36:14 in what is in reality just a second or two.

Console output from running codeceptjs run -c tests/acceptance/codecept.conf.js "--steps"
(The first part is just a log in script that runs before the test)

Patient administration --
 I can add a new patient
 • I am on page "/login"
 • I fill field "username", "root"
 • I fill field "password", "dx er en doc in a box"
 • I see "LOGG INN"
 • I see element in d o m "[name=loginBtn]"
 • I click "loginBtn"
 • I wait 1
 • I dont see "LOGG INN"
   this is a test
 • I am on page "/encounter/new"
   starting to fill fields at Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "[name=nationalId]", "13097335557"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "[name=age]", "63"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "[name=gender]", "63"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "[name=firstName]", "Kalle"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "[name=lastName]", "Kalle"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "#priority", "2"
   filled Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I fill field "#problem", "something fishy"
   Filling finished at Fri Jun 23 2017 13:35:20 GMT+0200 (CEST). Starting to click.
 • I click "#appdetailsheader button"
   click finished Fri Jun 23 2017 13:35:20 GMT+0200 (CEST)
 • I wait 1
 • I execute script function()
   new path: /patient/list/responsible, Fri Jun 23 2017 13:36:14 GMT+0200 (CEST)
 ✓ OK in 54159ms

Provide test source code if related

const assert = require('assert');

Feature('Patient administration');

Before(require('./login'));

Scenario('I can add a new patient', function *(I) {
  I.say('this is a test');
  I.amOnPage('/encounter/new');

  I.say(`starting to fill fields at ${Date()}`);
  I.fillField('[name=nationalId]', '13097335557');
  I.say(`filled ${Date()}`);
  I.fillField('[name=age]', '63'); // TODO: should be auto-filled from pnr
  I.say(`filled ${Date()}`);
  I.fillField('[name=gender]', 'M'); // TODO: should be auto-filled from pnr
  I.say(`filled ${Date()}`);
  I.fillField('[name=firstName]', 'Kalle'); 
  I.say(`filled ${Date()}`);
  I.fillField('[name=lastName]', 'Kalle'); 
  I.say(`filled ${Date()}`);
  I.fillField('#priority', '2'); 
  I.say(`filled ${Date()}`);
  I.fillField('#problem', 'something fishy'); 
  I.say(`Filling finished at ${Date()}. Starting to click.`);
  I.click('#appdetailsheader button');
  I.say(`click finished ${Date()}`);
  // takes about 30 seconds to get here

  I.wait(1);

  path = yield I.executeScript(()=>{
    return location.pathname;
  });
  I.say(`new path: ${path}, ${Date()}`);
  assert.notEqual(path, '/encounter/new');
});

Details

• CodeceptJS version: 0.6.3
• NodeJS Version: 8.0.0
• Operating System: Ubuntu 16.04
• WebDriverIO: 4.8.0
• Configuration file:

exports.config = {
  'tests': './*_test.js',
  'timeout': 10000,
  'output': './output',
  'helpers': {
    'WebDriverIO' : {
      'browser': 'chrome',
      'desiredCapabilities': {
        'browserName': 'chrome',
        'chromeOptions': {
          'args': [
            'NOT-READY-headless',
            'disable-gpu'
          ]
        }
      },
      'windowSize': '320x568',
      'restart': false,
      'timeouts': {
        'script': 10000,
        'page load': 3000,
        'implicit' : 5000
      },
      'url': process.env['CODECEPT_METEOR'] || 'http://localhost:23450'
    }
  },
  'include': {
    'I': './steps_file.js'
  },
  'bootstrap': './server-setup-teardown.js',
  'teardown': './server-setup-teardown.js',
  'mocha': {},
  'name': 'MyApp acceptance tests',
  'windowSize': '320x568'
};

[APshenkin]

@fatso83
CodeceptJS doesn't block any things from its side. So I think we have to take some investigation:

• First, try to do the same thing with WebdriverIO only. If problem will be still actual then you should ask WebdriverIO community about this error.
• Second, check Selenium logs and synchronise it with you test execution logs. CodeceptJS wait promise after each step, so if your Selenium server doesn't do these steps quickly, then it may be issue with Selenium and your site.

Note that CodeceptJS wait promise from WebdriverIO that waits result from Selenium server. In first we should localize the problem

[fatso83]

I tried rewriting it in pure WebdriverIO last Friday. That test passed in a few seconds. No lagging between input fields, everything whizzing through very quickly.

meteor node node_modules/.bin/wdio 

navigating Mon Jun 26 2017 10:10:50 GMT+0200 (CEST)
filling Mon Jun 26 2017 10:10:51 GMT+0200 (CEST)
clicked Mon Jun 26 2017 10:10:52 GMT+0200 (CEST)
finished Mon Jun 26 2017 10:10:53 GMT+0200 (CEST)
․

1 passing (13.10s)

const assert = require('assert');

const doLogin = () => {
  browser.url('/login');
  browser.waitForText('header h1','Innlogging')
  browser.setValue('[name=username]', 'root')
  browser.setValue('[name=password]', 'somepass')
  browser.click('[name=loginBtn]');

  browser.waitUntil( function() {
    return !browser.isExisting('[name=loginBtn]');
  });
  assert(!browser.getUrl().match(/\/login/));
}

describe('patient adding scenario', function() {
  before(doLogin);


  it('should be able to add an encounter', ()=>{
    console.log('navigating', new Date)
    browser.url('/encounter/new');

    browser.waitUntil( function() {
      return browser.isExisting('[name=lastName]')
    });

    console.log('filling',new Date)
    browser.setValue('[name=nationalId]', '13097335557');
    browser.setValue('[name=age]', '63'); // TODO: should be auto-filled from pnr
    browser.setValue('[name=gender]', 'M'); // TODO: should be auto-filled from pnr
    browser.setValue('[name=firstName]', 'Kalle'); 
    browser.setValue('[name=lastName]', 'Kukkian'); 
    browser.setValue('#priority', '2'); 
    browser.setValue('#problem', 'something fishy'); 
    browser.click('#savebtn');
    console.log('clicked',new Date)

    browser.waitUntil( function() {
      return !browser.isExisting('[name=lastName]');
    });
    console.log('finished',new Date)
  });
});

As for the Selenium logs, there is nothing much to go by, so maybe you could provide me with a hint? This is all I get - even with debug enabled (which does not seem to do much):

$ selenium-standalone start -- -debug true
2017-06-26 09:55:29.457:INFO::main: Logging initialized @318ms to org.seleniumhq.jetty9.util.log.StdErrLog
2017-06-26 09:55:29.578:INFO:osjs.Server:main: jetty-9.4.3.v20170317
2017-06-26 09:55:29.625:INFO:osjsh.ContextHandler:main: Started o.s.j.s.ServletContextHandler@4135c3b{/,null,AVAILABLE}
2017-06-26 09:55:29.639:INFO:osjs.AbstractConnector:main: Started ServerConnector@79079097{HTTP/1.1,[http/1.1]}{0.0.0.0:4444}
2017-06-26 09:55:29.640:INFO:osjs.Server:main: Started @501ms
Selenium started
Starting ChromeDriver 2.30.477691 (6ee44a7247c639c0703f291d320bdf05c1531b57) on port 17058
Only local connections are allowed.
Starting ChromeDriver 2.30.477691 (6ee44a7247c639c0703f291d320bdf05c1531b57) on port 15928
Only local connections are allowed.

Using Firefox only brings a few additional lines

1498465065319   geckodriver INFO    Listening on 127.0.0.1:21926
1498465065383   geckodriver::marionette INFO    Starting browser /usr/lib/firefox/firefox with args ["-marionette"]
1498465067238   Marionette  INFO    Listening on port 34477
JavaScript warning: http://localhost:3000/packages/markoshust_nouislider.js?hash=2d133893b2061eb5782cac5a1b985e4d6dcc8cea, line 0: http://localhost:3000/packages/markoshust_nouislider.js?hash=2d133893b2061eb5782cac5a1b985e4d6dcc8cea is being assigned a //# sourceMappingURL, but already has one
JavaScript warning: http://localhost:3000/packages/markoshust_nouislider.js?hash=2d133893b2061eb5782cac5a1b985e4d6dcc8cea, line 0: http://localhost:3000/packages/markoshust_nouislider.js?hash=2d133893b2061eb5782cac5a1b985e4d6dcc8cea is being assigned a //# sourceMappingURL, but already has one
1498465132790   Marionette  INFO    New connections will no longer be accepted

[APshenkin]

I.fillfield() command clear the field first and then put the value to the field
return this.elementIdClear(elem.ELEMENT).elementIdValue(elem.ELEMENT, value);
So maybe problem is with clearing field? Try to use I.appendField() in codecept tests or add clearField in webdriverIO example

About selenium-standalone logs - do you use some custom config? Try to reinstall selenium-standalone and run it again. By default it print logs from drivers

[fatso83]

I tried changing to appendField. No change. I also tried changing the wdio script. No change. But I found something very interesting in the logs ...

Took some time to find out how to get more explicit logs, as none of the Selenium settings took effect. Turns out that

By default ChromeDriver logs only warnings/errors to stderr. When debugging issues, it is helpful to enable more verbose logging.

After manually hacking the selenium-standalone package I got to set webdriver.chrome.logfile variable and got a 700 line file with the driver details of what was going on.

The most interesting bits are grep -C5 'waiting for pending navigations' ~/chromedriver.log:

[27,947][INFO]: Waiting for pending navigations...
[27,949][INFO]: Done waiting for pending navigations. Status: ok
[32,965][INFO]: Waiting for pending navigations...
[32,965][INFO]: Done waiting for pending navigations. Status: ok
[32,965][INFO]: RESPONSE FindElements [  ]
[32,972][INFO]: COMMAND FindElements {
   "using": "css selector",
   "value": "[name=age]"
}
[32,972][INFO]: Waiting for pending navigations...
[32,974][INFO]: Done waiting for pending navigations. Status: ok
[32,987][INFO]: Waiting for pending navigations...
[32,992][INFO]: Done waiting for pending navigations. Status: ok
[32,992][INFO]: RESPONSE FindElements [ {
   "ELEMENT": "0.603445362359257-2"
} ]
[33,003][INFO]: COMMAND ClearElement {
   "id": "0.603445362359257-2"
}
[33,003][INFO]: Waiting for pending navigations...
[33,004][INFO]: Done waiting for pending navigations. Status: ok
[33,022][INFO]: Waiting for pending navigations...
[33,022][INFO]: Done waiting for pending navigations. Status: ok
[33,022][INFO]: RESPONSE ClearElement
[33,029][INFO]: COMMAND TypeElement {
   "id": "0.603445362359257-2",
   "value": [ "6", "3" ]
}
[33,029][INFO]: Waiting for pending navigations...
[33,033][INFO]: Done waiting for pending navigations. Status: ok
[33,102][INFO]: Waiting for pending navigations...
[33,105][INFO]: Done waiting for pending navigations. Status: ok
[33,105][INFO]: RESPONSE TypeElement
[33,115][INFO]: COMMAND FindElements {
   "using": "xpath",
   "value": ".//*[self::input | self::textarea | self::select][not(./@type = 'submit' or ./@type = 'image' or ./@type = 'hidden')][(((./@name = '[name=gender]') or ./@id = //label[contains(normalize-space(strin..."
}
[33,115][INFO]: Waiting for pending navigations...
[33,116][INFO]: Done waiting for pending navigations. Status: ok
[38,118][INFO]: Waiting for pending navigations...
[38,119][INFO]: Done waiting for pending navigations. Status: ok
[38,119][INFO]: RESPONSE FindElements [  ]
[38,125][INFO]: COMMAND FindElements {
   "using": "xpath",
   "value": ".//*[self::input | self::textarea | self::select][@name = '[name=gender]']"
}
[38,126][INFO]: Waiting for pending navigations...
[38,126][INFO]: Done waiting for pending navigations. Status: ok
[43,152][INFO]: Waiting for pending navigations...

As you can see, there is a 5 second delay after each "Done waiting for pending navigations". That only happens for this one test, not the other ones.

[APshenkin]

Have no idea what is it.

BTW, when I mentioned logs from selenium server I say about these logs:

14:53:01.408 INFO - Executing: [set window size])
14:53:01.408 INFO - Executing: [get: https://github.com])
14:53:01.770 INFO - Done: [set window size]
14:53:04.079 INFO - Done: [get: https://github.com]

These logs are from Selenium server itself can you please provide them for WebdriverIO example and CodeceptJS example?

[lisettea]

I have encountered this issue several times. In my case it was always an outdated drivers at fault. - downloading the latest driver versions would kickstart the test back to their proper speed. Maybe updating your chrome driver would help?

[DavertMik]

Ok, I see the issue

@fatso83 you are using implcit waits

'implicit' : 5000

and wide locators. When you use [name=xx] locator, like

I.fillField('[name=firstName]', 'Kalle'); 

CodeceptJS does not understand that this is CSS. At first it tries to find a text field by its label, then by name, then tries standard locators. It's 3 calls, but usually it doesn't matter. However, in your config it will wait for 5 seconds in each unsuccessful case. So each call is stuck for 10 seconds at least.

What you can do.

• Disable implicit waits. They are evil if used incorrectly. And in most cases they are.
• or use strict locators, like { css: '[name=firstName]' } to specify the locator type

you can also change implicit timeouts dynamically with defineTimeout so you can turn implicit waits on and off

[fatso83]

That's fantastic debugging. I was unaware of the implications of implicit wait in conjunction with css locators.

[bwaybandit]

Using NightmareJS 3.0.0 with codeceptJS and ran into this. I had to set "typeInterval" property in NightmareJS to -1. Might not be the same issue but i thought this might help someone else. All good points above though.

Example below:
"helpers": {
"Nightmare": {
"url": "https://access.dev.secureauth.com/246/users/sign_in",
"show": true,
"windowSize": "1440x1024",
"waitforTimeout": 1000,
"typeInterval": -1,
"desiredCapabilities": {
"browserName": "chrome",
"chromeOptions": {
"args": "['start-maximized']"
}
}
},
"MyHelper": {
"require": "./common/codeceptjsCommon.js"
}
},