Test output gets mixed up when run in parallel

[f1ames]

This issue was initially reported in cucumber/cucumber-js as cucumber/cucumber-js#1949. See discussion there why it was moved here.

👓 What did you see?

When tests are run with --parallel flag, the output (for example, steps description) gets mixed.

When run without --parallel option:

With --parallel you can see that scenarios (and steps) are printed as they come from different workers and get mixed:

✅ What did you expect to see?

I would expect that each Scenario (or entire Feature, so could be multiple scenarios) would be printed as a whole, one after another.

📦 Which version are you using?

"@cucumber/cucumber": "^7.3.2",
"@cucumber/pretty-formatter": "^1.0.0-alpha.1",

🔬 How could we reproduce it?

I'm coming from Scramjet and we are using Cucumber for running BDD tests in multiple repos. The screenshots are based on tests from https://github.com/scramjetorg/transform-hub. You can reproduce it by running tests from this repo:

git clone https://github.com/scramjetorg/transform-hub.git
cd transform-hub
yarn install && yarn build:all
yarn test:bdd-ci --name="E2E" --parallel 4

Please keep in mind you may need some stuff from setup steps too.

🤔 Anything else?

I'm happy to provide more details/context if needed.

[vacharanon]

What I did is to try easing up this issue by prefixing every line with [${testCaseStartedId}].
So that even they're mixed up, I can use search to visually distinguish each scenario.

[437] And I should see "xxx"
[437] When I tap "yyy"
[ce7] Then I should see "aaa"
[ce7] When I scroll "bbb" down until I see "ccc"

[mpkorstanje]

As mentioned in the original issue, the usecase is to view a summary in the CLI rather a realtime progress report.

Without parallel execution the pretty formatter can handle both usecases. With parallel execution this is different.

There are several options for this and we generally try to keep implementations in different languages in sync. I'll put this on the agenda for the next contributors call.

An option would be prefixing each log line with a sortable identifier. This identifier could be composed of <feature file index><line in feature file> <timestamp>. If all numbers are zero-padded simple tools like sort could take care of this.

Yet another option would be to make the plugin --parallel aware and only print the results of a scenario when the entire scenario is finished.

It could also be an idea to create a second formatter pretty-summary which works like the pretty formatter but only prints everything at the end of a run.

There is also the possibility to make a tool that consumes the output from the messages formatter and feeds it to the pretty formatter.

The latter two solutions require that tbe plugin recieces the events in order or sorts them.

In Cucumber JVM we have several plugins that must receive their events in order. We solve this by collecting and then sorting the events.

Unfortunately this comes at a significant overhead in terms of memory. Additionally Cucumber JVM uses its own events which are sortable. The messages used in the pretty formatter aren't quite as easy to sort (though not impossible).

[mattwynne]

Although there don't appear to be any tests for it in this repo, I tried it manually and this formatter works well when cucumber-js is run in --order random mode: outputting each scenario with the enclosing Feature above it.

I suggest we adopt that strategy for parallel execution too - roll up the output for each scenario and emit it to the console (with the enclosing Feature / Rule) once we hear a TestCaseFinished message.

Ideally I guess we could signal in an earlier message (e.g. TestRunStarted?) whether the run is happening in parallel so that we could keep the "live feel" for test runs that aren't happening in parallel, without the user having to specify any extra configuration.

[mattwynne]

There is also the possibility to make a tool that consumes the output from the messages formatter and feeds it to the pretty formatter.

I like this idea. In single-responsibility terms it would be useful to have a "module" of some kind that can consume a stream of interleaved messages and emit them with the messages about each test case grouped together.

We could built it as a javascript function and then potentially also package it as a CLI tool for piping.

[mpkorstanje]

I suggest we adopt that strategy for parallel execution too - roll up the output for each scenario and emit it to the console (with the enclosing Feature / Rule) once we hear a TestCaseFinished message.

I think I this will work well but when Cucumber gets stuck or takes a long time when executing serially will leave people wondering what scenario they're stuck on.

So in addition I would suggest we implement a toggle (like we enable/disable ANSI colors) for parallel execution. Cucumber knows when it run in parallel so it can switch strategies.

[J-Henke]

Dear all,
are there any plans on fixing the here described issue?
Best regards
Jan

[samireshi]

Any updates on this?

[mattwynne]

I don't have time at the moment to own the solution to this, but I would happily pair with a contributor who wants to.

You can book a slot with me here.

You're also welcome to join us in our community Slack in the #committers channel 😄 where we can chat about it.

[OleksiiHryhorian]

+1.
Same issue on my side. Trying to figure out how to overcome that

[OleksiiHryhorian]

What I did is to try easing up this issue by prefixing every line with [${testCaseStartedId}]. So that even they're mixed up, I can use search to visually distinguish each scenario.

[437] And I should see "xxx"
[437] When I tap "yyy"
[ce7] Then I should see "aaa"
[ce7] When I scroll "bbb" down until I see "ccc"

Hey requiem202, could you please clarify where did you add this [${testCaseStartedId}] to output console? Feature file / steps / formatter ?
Thank you in advance !