running tests in parallel creates a very bad logging

[AlaaSayed794]

Describe the bug

when I run tests in parallel the console has test names overlapping and also there are weird squares logging after the test using v2.0.10 which were not there when I used to use v2.0.5

Verbose output

debug.log

```txt Started child process for: test8.js\test1.js Started child process for: test8.js\test2.js Started child process for: test8.js\test3.js Started child process for: test8.js\test4.js Started child process for: test8.js\test5.js Started child process for: test8.js\test6.js Started child process for: test8.js\test7.js Started child process for: test8.js\test8.js Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... Starting Selenium Server [selenium-server-standalone-3.141.59.jar] on port 4444... [default: test1.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test3.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test2.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test6.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test4.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test7.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test5.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... [default: test8.js example test] Test Suite ─────────────────────────────────────────────────────────────────────────────── - Connecting to 127.0.0.1 on port 4444... i Connected to 127.0.0.1 on port 4444 (2472ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test3.js [default: test3.js example test] ok Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── i Connected to 127.0.0.1 on port 4444 (2615ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test1.js [default: test1.js example test] ok Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── i Connected to 127.0.0.1 on port 4444 (2996ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test5.js [default: test5.js example test] ok (24ms) Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── i Connected to 127.0.0.1 on port 4444 (3545ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── i Connected to 127.0.0.1 on port 4444 (3763ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ Passed [ok]: true ok √ test8.js\test7.js [default: test7.js example test] ok (25ms) √ test8.js\test6.js [default: test6.js example test] ok Running End: Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── ─────────────────────────────────────────────────────────────────────────────────────────────────── √ test8.js\test3.js [default: test3.js example test] End (1.613s) i Connected to 127.0.0.1 on port 4444 (3928ms). √ test8.js\test1.js [default: test1.js example test] End (1.708s) Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test4.js [default: test4.js example test] ok (21ms) Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── i Connected to 127.0.0.1 on port 4444 (4238ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test2.js [default: test2.js example test] ok Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ test8.js\test5.js [default: test5.js example test] End (1.067s) √ test8.js\test7.js [default: test7.js example test] End (552ms) √ test8.js\test4.js [default: test4.js example test] End (439ms) √ test8.js\test6.js [default: test6.js example test] End (640ms) √ test8.js\test2.js [default: test2.js example test] End (297ms) i Connected to 127.0.0.1 on port 4444 (3234ms). Using: chrome (100.0.4896.75) on WINDOWS. Running ok: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ Passed [ok]: true ok √ test8.js\test8.js [default: test8.js example test] ok Running End: ─────────────────────────────────────────────────────────────────────────────────────────────────── √ test8.js\test8.js [default: test8.js example test] End (77ms) ┌ ────────────────── √ test8.js\test3.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test1.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test7.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test4.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test2.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test5.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test6.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ ┌ ────────────────── √ test8.js\test8.js ┐ │ │ │ │ │ │ └──────────────────────────────────────────┘ OK. 8 total assertions passed (17.653s) ```

Your Environment

Executable	Version
nightwatch --version	2.0.10
npm --version	8.3.1
node --version	v16.14.0

Browser driver	Version
chromedriver	100.0.0

| NAME | VERSION |

OS	Version
windows	10

[beatfactor]

Can you post your config as well?

[beatfactor]

Also can you try using our own selenium package? I recommend upgrading to Selenium 4, but if you want to use version 3 still, you can install it with:

npm i @nightwatch/selenium-server@3

Using this package should only start one instance of the Selenium server and then only start child processes that connect to this instance.

The package is available here: https://github.com/nightwatchjs/selenium-server-jar-download

[AlaaSayed794]

@beatfactor this issue occurs when running tests in parallel

I could use your selenium version, but we also run tests on browserstack and I have the same weird logs there

{
  "webdriver": {
    "keep_alive": true
  },
  "test_workers": {
    "enabled": true,
    "workers": 8
  },
  "test_settings": {
    "default": {
      "skip_testcases_on_fail": false,
      "launch_url": "http://hub-cloud.browserstack.com/wd/hub",
      "selenium_port": 443,
      "selenium_host": "hub.browserstack.com",
      "silent": true,
      "exclude": [
        "tests/*sample*.js"
      ],
      "end_session_on_fail": false,
      "screenshots": {
        "enabled": false,
        "path": ""
      },
      "desiredCapabilities": {
        "os": "windows",
        "os_version": "10",
        "browserName": "chrome",
        "browser_version": "latest",
        "resolution": "1920x1080",
        "javascriptEnabled": true,
        "acceptSslCerts": true,
        "browserstack.user": "my user",
        "browserstack.key": "my key",
        "browserstack.debug": true,
        "browserstack.video": true,
        "browserstack.local": false,
        "browserstack.selenium_version": "3.141.59",
        "browserstack.networkLogs": true,
        "browserstack.networkLogsOptions": {
          "captureContent": true
        },
        "browserstack.console": "errors",
        "browserstack.use_w3c": true,
        "browserstack.idleTimeout": 300
      }
    }
  },
  "live_output": true,
  "detailed_output": true,
  "test_runner": {
    "type": "default",
    "options": {
      "bail": false,
      "retries": 0
    }
  },
  "selenium": {
    "start_process": false,
    "host": "hub.browserstack.com",
    "port": 443
  }
}

[beatfactor]

Ok, try setting live_output to false. That should make it better I think.

[AlaaSayed794]

I don't think this solves the issue. I'm reporting a bug that the logging in the live output doesn't look good and you're telling me to just turn it off.

[beatfactor]

Yes, that's right. That will solve the issue.

Live output means that the output from every child process will be sent to the terminal as it happens, but if you turn it off it will be buffered until the child process stops executing and will be displayed together as one block. Live output cannot be user-friendly, that's why it's turned off by default, and it's only meant to be on for debugging purposes.

If you try it out you'll see what I mean and I am confident that it will solve your problem. In any case, there isn't much we can do. Another alternative will be to set detailed_logging to false, but that just means that less stuff is displayed.

[AlaaSayed794]

it even looks uglier

[AlaaSayed794]

I think it is something wrong in boxen , maybe it was not designed to encapsulate this much text

I get normal logs which really looks a bit better on version 2.0.6 and when I removed boxen and just logged this.env_output in concurrency/child-process.js

[AlaaSayed794]

also for the weird logs of two adjacent tests,

I get what went wrong here.

I have a folder where I wanted to run specific tests but not all of them, why I didn't use tags is a long story, but what I did is that I specified these tests to the configuration attribute src_folders

it seems that nightwatch doesn't handle this well when I run them in parallel.

I could fix it without changing much in the code https://github.com/nightwatchjs/nightwatch/pull/3139

[beatfactor]

Ok, I see. Which terminal is it? I think we haven't tested this well enough on Windows terminals and we'll probably need to disable boxen. It should be disabled in any case if detailed_output is false.

[AlaaSayed794]

both command prompt and bash.

[swrdfish]

@AlaaSayed794 I could not reproduce the issue with windows 10, using nightwatch v2.0.10 or v2.3.3

The only time logs get deformed is when I resize the terminal window while nightwatch is executing. Maybe this has to do with the terminal window size?

[AutomatedTester]

@AlaaSayed794 Is this fixed? We have done a number of fixes in this area and aren't able to reproduce it anymore.

[AlaaSayed794]

@AutomatedTester this is not fixed, to reproduce : src_folders has a list of relative paths to the tests , e.g: "src_folders": [ "tests/case-details/test1.js", "tests/case-details/test2.js",........], "test_workers": { "enabled": true, "workers": x }, "live_output": true, "detailed_output": true,

I tried this on v2.6.3 (the latest today) and this is what I got :

the reason is that if (filePath.indexOf(folder) === 0) { in lib/utils/index.js getModuleKey function never breaks

I submitted a fix for it

[AlaaSayed794]

https://github.com/nightwatchjs/nightwatch/pull/3539

[AlaaSayed794]

this is what I get when applying this