Output is generated only after running all features

[fslev]

Output is only generated after running all features

Hi, I am using cucumber-jvm version 4.2.0 When I am running all features via JUnit and Maven, no output with the running scenarios steps is displayed. The features, scenarios and the corresponding steps results are displayed only when all cucumber tests finish. After changing cucumber-jvm version to 3.0.2, I saw that the output from Cucumber (running features, scenarios and steps) is displayed in real time.

[mpkorstanje]

To resolve this problem the PrettyFormatter should implement the ConcurrentEventListener and be able to handle events from the concurrent execution of pickles (e.g. when using --parallel). See the v4 release announcement for more details.

Please feel free to send PR!

[scormaq]

@mpkorstanje does cucumber-jvm have (or it's in plans to have) integration with logging frameworks like log4j, slf4j etc?

I'm afraid that in case of parallel running cucumber tests, output from pretty formatter will be messed up with logger messages, because for now there no such integration. Example:

• I'm using cucucumber-jvm 4.2.1 + log4j2 + slf4j

• I'm running next feature file with 3 threads in parallel:  
  

  Feature: very first cucumber test
  
  Scenario: first scenario
  Given I report next in log: 'Hello from 1st scenario'
  
  Scenario: second scenario
  Given I report next in log: 'Hello from 2nd scenario'
  
  Scenario: third scenario
  Given I report next in log: 'Hello from 3rd scenario'
  
  Scenario: fourth scenario
  Given I report next in log: 'Hello from 4th scenario'

  
  
  

1) Here is how my console logs look like when PrettyFormatter implements EventListener

Console output:

```cmd > Task :cucumberTests 17:23:24 [pool-2-thread-3] INFO : Hello from 3rd scenario 17:23:24 [pool-2-thread-1] INFO : Hello from 1st scenario 17:23:24 [pool-2-thread-2] INFO : Hello from 2nd scenario 17:23:25 [pool-2-thread-2] INFO : Hello from 4th scenario Feature: very first cucumber tests] Scenario: first scenario # src/test/resources/features/First.feature:4 Given I report next in log: 'Hello from 1st scenario' # SomeDefs.logSomething(String) Scenario: second scenario # src/test/resources/features/First.feature:7 Given I report next in log: 'Hello from 2nd scenario' # SomeDefs.logSomething(String) Scenario: third scenario # src/test/resources/features/First.feature:10 Given I report next in log: 'Hello from 3rd scenario' # SomeDefs.logSomething(String) Scenario: fourth scenario # src/test/resources/features/First.feature:13 Given I report next in log: 'Hello from 4th scenario' # SomeDefs.logSomething(String) ```

**2)** Here is how console logs might look like if `PrettyFormatter` implement `ConcurrentEventListener`

Console output:

```cmd > Task :cucumberTests Feature: very first cucumber test Scenario: first scenario # src/test/resources/features/First.feature:4 Scenario: second scenario # src/test/resources/features/First.feature:7 Scenario: third scenario # src/test/resources/features/First.feature:10 17:27:49 [pool-2-thread-2] INFO : Hello from 2nd scenario 17:27:49 [pool-2-thread-3] INFO : Hello from 3rd scenario 17:27:49 [pool-2-thread-1] INFO : Hello from 1st scenario Given I report next in log: 'Hello from 1st scenario' # SomeDefs.logSomething(String) Given I report next in log: 'Hello from 2nd scenario' # SomeDefs.logSomething(String) Given I report next in log: 'Hello from 3rd scenario' # SomeDefs.logSomething(String) Scenario: fourth scenario # src/test/resources/features/First.feature:13 17:27:50 [pool-2-thread-2] INFO : Hello from 4th scenario Given I report next in log: 'Hello from 4th scenario' # SomeDefs.logSomething(String) ```

I copied to my project `PrettyFormatter` class and made it implement `ConcurrentEventListener`. Did not help a lot.

**3)** And actually I would like to see my scenario execution along with its logs, like this:

Console output:

```cmd > Task :cucumberTests Feature: very first cucumber test Scenario: third scenario # src/test/resources/features/First.feature:10 17:52:54 [pool-2-thread-3] INFO : Hello from 3rd scenario Given I report next in log: 'Hello from 3rd scenario' # SomeDefs.logSomething(String) Scenario: first scenario # src/test/resources/features/First.feature:4 17:52:54 [pool-2-thread-1] INFO : Hello from 1st scenario Given I report next in log: 'Hello from 1st scenario' # SomeDefs.logSomething(String) Scenario: second scenario # src/test/resources/features/First.feature:7 17:52:54 [pool-2-thread-2] INFO : Hello from 2nd scenario Given I report next in log: 'Hello from 2nd scenario' # SomeDefs.logSomething(String) Scenario: fourth scenario # src/test/resources/features/First.feature:13 17:52:55 [pool-2-thread-3] INFO : Hello from 4th scenario Given I report next in log: 'Hello from 4th scenario' # SomeDefs.logSomething(String) ```

Here, my log4j2 logs and `PrettyFormatter` are not printed immediately as they arrive, but buffered and printed once scenario finished, so I have clear console reporting per scenario.

[mpkorstanje]

does cucumber-jvm have (or it's in plans to have) integration with logging frameworks like log4j, slf4j etc?

Cucumber development is currently primarily driven by community contributions. As such plans exist by the grace of its contributors. I'm currently not aware of prospective contributions in that area.

@mlvandijk had a look at this a while ago but we concluded that in that state of the code base it was not feasible. The current state has been somewhat improved. So it might be worth taking a second look.

As a test framework Cucumber should be relatively dependency free -- lest our dependencies interfere with the system under test. This rules out log4j and slf4j.

It is possible to use use java.util.logging.Logger but I'm concerned about the performance impact of JUL under Java 7. Upgrading Cucumber to Java 8 to facilitate lazy log message creation should be fine though.

I'm afraid that in case of parallel running cucumber tests, output from pretty formatter will be messed up with logger messages, because for now there no such integration. Here, my log4j2 logs and PrettyFormatter are not printed immediately as they arrive, but buffered and printed once scenario finished, so I have clear console reporting per scenario.

Buffering the the the test case events should be entirely possible. Each TestCaseEvent has a reference to its associated test case and each event listener is synchronized. It does not have to process events concurrently, only test cases.

I'm not sure how you'd make it sync up with the log messages though. How would you propose doing this?

Either way if you get it to work I'd be happy accept the improved formatter as a PR!

[scormaq]

I'm not sure how you'd make it sync up with the log messages though. How would you propose doing this?

I thought about storing cucumber event logs and logger logs into some map (e.g. ConcurrentHashMap) and then printing all collected logs at TestCaseFinished event. Not sure about performance, but it should not affect it a log. At least, for me it's a nice trade off - to have readable console output.

Here is demo project: https://github.com/scormaq/cucumber4-parallel-logger I did some refactoring with pretty formatter here, with it user can change using pretty plugin to improved log formatter (for log4j2, but it can be extended for other logging frameworks too).

I did not test it for performance or some edge cases, but at first glance it look nice to me. If you think that it is OK, I can propose it to pull request.

[mpkorstanje]

Ah. I see. You're buffering the output of the formatter. Pretty neat. Unfortunately I was expecting the input to be buffered. I'd rather not stack adhoc adapters in the framework itself. It makes the implementation harder to follow.

[TepidDrink]

I am using IntelliJ and running several large feature files. So with cucumber v4 I have to wait until the whole feature file has been run until I see a hierarchical test output, whereas with v3.0.2 and before I do not. There is no documentation for the fix and I guess there is none, no mentions of the reasoning behind this change, and it slows me down! Has anyone got any ideas? I don't want to be running tests in parallel, they are all calling the same api, I just want to see the progress as I'm running the feature file and to have the hierarchical view as follows: Features.Scenarios.Tests.Steps

[mpkorstanje]

IntelliJs "Cucumber for Java" plug-in will have to be updated. You can check https://youtrack.jetbrains.com to see if this issue has been reported yet and vote for it, or create an issue yourself.

Looking at https://github.com/JetBrains/intellij-community/commit/93dbc50fc0715f6229688650bc94ec72702bc340 it would appear this should have been fixed in IDEA 191 though.

[fslev]

Hi, Any feedback about the status of this issue ? Or is there a workaround to see real-time test status progress via scenario.write() ? Regards, Florin

[mpkorstanje]

From the read me:

Please bear in mind that this project is almost entirely developed by volunteers. If you do not provided the implementation yourself (or pay someone to do it for you), the bug might never get fixed. If it is a serious bug, other people than you might care enough to provide a fix.

[MateuszMysliwiec]

I started having the same issue after updating to 4.2.6 versions

[timtebeek]

Just came across this issue.. Would a naive implementation work where the PrettyFormatter appends all output per test case to a String builder, and writes that to the argument Appendable as each test case is finished?

I agree that log output would still be misplaced, but that's similar to what we have to currently already, with the exception that it would then interleave with the pretty output. Logging could then be tackled separately if needed.

[mpkorstanje]

The primary obstacle to concurrent execution is that formatter keeps track of the currentFeatureFile, currentTestCase, currentScenarioOutline andcurrentExamples. These would all need to be tracked on a per feature basis. Once this is done I think it'd be possible to print the events as they happen. The formatting will be off but at least the steps are printed as they're executed.

Anyway I'm not entirely convinced a satisfying solution is possible. The pretty formatter renders a facsimile of the original feature file. This includes the feature title, description, a grouped up background steps. These are inherently unsuitable to be displayed in any sort of atomic fashion. For instance any parallel run would start by printing n feature titles and descriptions.

But perhaps we can down scope the problem a bit. We could perhaps ensure that when Cucumber does not run in parallel the output is generated immediately. If we could find a way to avoid using the CanonicalOrderEventPublisher when the Cucumber JUnit runner, the CLI or the AbstractTestNGCucumberTests is not being ran in parallel we'd have most of the problem solved.

[timtebeek]

OK; based on the comments by Rien above I've made an attempt at doing just that: ensuring that for the single-thread use case we immediately pass events to plugins again, thus triggering the text output.

[nicholaswkc34]

Any example on how to implement ConcurrentEventListener?

[timtebeek]

@peterwkc85 you can implement a ConcurrentEventListener the same as you would a normal EventListener; it only depends on what you do with the events that you consume:

• If you're generating text output to the screen for instance, you'd need to be aware that events from different tests can arrive interleaved, so you might want to group them before printing to the screen.
• If you're creating a summary of events received then the order might not matter at all, so you need not change your code in that case.

[fgolygo]

hey @timtebeek and @mpkorstanje 4 years passed. Did anything change regarding displaying parallel test logs correctly?