No information about steps in console log

[dip56]

We use information in console log in our reports, can you return this feature back? It's very useful information if you use some loggers in different modules.

console log since 1.1.22-rc.8:

TEST STARTED: shouldBeAbleToAddPetsToAStore
-------------------------------------------------------------------
[main] INFO net.serenitybdd.core.Serenity - TEST NUMBER: 1
{
    "id": 1320964950,
    "name": "fido",
    "photoUrls": [

    ],
    "tags": [

    ],
    "status": "available"
}
{
    "id": 1320964950,
    "name": "fido",
    "photoUrls": [

    ],
    "tags": [

    ],
    "status": "available"
}
[main] INFO net.serenitybdd.core.Serenity - 

version 1.1.22-rc.4:

TEST STARTED: shouldBeAbleToAddPetsToAStore
--------------------------------------------------------------------
[main] INFO net.serenitybdd.core.Serenity - TEST NUMBER: 1
[main] INFO net.thucydides.core.steps.StepInterceptor - STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleToAddPetsToAStore - when_i_add_the_pet_to_the_store
{
    "id": 888589568,
    "name": "fido",
    "photoUrls": [

    ],
    "tags": [

    ],
    "status": "available"
}
[main] INFO net.thucydides.core.steps.StepInterceptor - STEP DONE: when_i_add_the_pet_to_the_store
[main] INFO net.thucydides.core.steps.StepInterceptor - STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleToAddPetsToAStore - the_pets_should_be_available
{
    "id": 888589568,
    "name": "fido",
    "photoUrls": [

    ],
    "tags": [

    ],
    "status": "available"
}
[main] INFO net.thucydides.core.steps.StepInterceptor - STEP DONE: the_pets_should_be_available
[main] INFO net.serenitybdd.core.Serenity - 

[dsmt]

+

[YamStranger]

Hello @dip56! Thanks for reporting this issue. I will try to help you.

It seems that we changed our logging level from info to debug - that's why I doesn't see some lines in your console log.

We use slf4j in code, so you can configure it with logback for example.

I am not sure that we log requst/response xml/json (output in logs not from serenity), so it could be fixed in #198.

Correct me if I am wrong, and my answer does'n help you to solve your problem.

Below you can find my short investigation:

I run in junit-webtest build with next command:

gradle clean test aggregate -Dtest.single=AddAPetToThePetStoreTest --info

and here is console output:

    TEST STARTED: shouldBeAbleDeletePetsFromAStore
    -------------------------------------------------------------------
    660  [Test worker] INFO  net.serenitybdd.core.Serenity - TEST NUMBER: 1
    689  [Test worker] DEBUG n.t.core.steps.StepInterceptor - STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleDeletePetsFromAStore - when_i_add_the_pet_to_the_store
    {
        "id": 1226622430,
        "name": "fido",
        "photoUrls": [

        ],
        "tags": [

        ],
        "status": "available"
    }
    2249 [Test worker] DEBUG n.t.core.steps.StepInterceptor - STEP DONE: when_i_add_the_pet_to_the_store
    2251 [Test worker] DEBUG n.t.core.steps.StepInterceptor - STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleDeletePetsFromAStore - when_i_delete_the_pet

I used build.gradle:

ext{
    serenity_version = "1.1.22-rc.8"
}

apply plugin: "java"
apply plugin: "eclipse"
apply plugin: "idea"
apply plugin: "net.serenity-bdd.aggregator"

buildscript {
    repositories {
        mavenLocal()
        jcenter()
    }
    dependencies {
        classpath("net.serenity-bdd:serenity-gradle-plugin:1.1.22-rc.8")
    }
}
test {
    systemProperties = [
        "logback.configurationFile": "logback.xml"
    ]
}

dependencies {
    compile localGroovy()
    compile "net.serenity-bdd:serenity-core:$serenity_version"
    compile "net.serenity-bdd:serenity-junit:$serenity_version"
    compile("net.serenity-bdd:serenity-rest-assured:$serenity_version")
    compile 'org.codehaus.groovy:groovy-all:2.3.10'
    compile 'junit:junit:4.12'
    compile 'com.googlecode.lambdaj:lambdaj:2.3.3'
    compile 'org.assertj:assertj-core:3.1.0'
    compile group: 'junit', name: 'junit', version: '4.+'
    compile group: 'ch.qos.logback', name: 'logback-classic', version: '1.+'
}

gradle.startParameter.continueOnFailure = true

also I used next logback.xml file

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type
             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
        </encoder>
    </appender>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>junit.log</file>
        <append>false</append>
        <!-- encoders are assigned the type
             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%-4r %-5level %logger{35}: %msg%n</pattern>
        </encoder>
    </appender>
    <root level="TRACE">
        <appender-ref ref="FILE" />
        <appender-ref ref="STDOUT" />
    </root>
    <!-- We want error logging from this logger to go to an extra appender
         It still inherits CONSOLE STDOUT from the root logger -->
    <logger name="junit" level="TRACE">
        <appender-ref ref="STDOUT" />
    </logger>
</configuration>

and in log I found next lines (junit.log in my situation):

TEST PASSED: Should be able delete pets from a store
----------------------------------------------------------------------------
2772 DEBUG n.s.j.r.RetryFilteringRunNotifier: Flushing notifications
2773 DEBUG n.s.j.r.RetryFilteringRunNotifier: Test started: shouldBeAbleToAddPetsToAStore(net.thucydides.showcase.junit.features.petstore.AddAPetToThePetStoreTest)
2774 DEBUG n.t.core.steps.StepEventBus: Test suite started for class net.thucydides.showcase.junit.features.petstore.AddAPetToThePetStoreTest
2774 INFO  net.serenitybdd.core.Serenity: Test Suite Started: Add a pet to the pet store test
2775 INFO  net.serenitybdd.core.Serenity:
 _____ _____ ____ _____   ____ _____  _    ____ _____ _____ ____
|_   _| ____/ ___|_   _| / ___|_   _|/ \  |  _ \_   _| ____|  _ \
  | | |  _| \___ \ | |   \___ \ | | / _ \ | |_) || | |  _| | | | |
  | | | |___ ___) || |    ___) || |/ ___ \|  _ < | | | |___| |_| |
  |_| |_____|____/ |_|   |____/ |_/_/   \_\_| \_\|_| |_____|____/

TEST STARTED: shouldBeAbleToAddPetsToAStore
-------------------------------------------------------------------
2776 INFO  net.serenitybdd.core.Serenity: TEST NUMBER: 2
2777 DEBUG n.t.core.steps.StepInterceptor: STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleToAddPetsToAStore - when_i_add_the_pet_to_the_store
2951 DEBUG n.t.core.steps.StepInterceptor: STEP DONE: when_i_add_the_pet_to_the_store
2953 DEBUG n.t.core.steps.StepInterceptor: STARTING STEP: AddAPetToThePetStoreTest.shouldBeAbleToAddPetsToAStore - the_pets_should_be_available
3514 DEBUG n.t.core.steps.StepInterceptor: STEP DONE: the_pets_should_be_available
3524 DEBUG n.s.j.r.RetryFilteringRunNotifier: Test finished: shouldBeAbleToAddPetsToAStore(net.thucydides.showcase.junit.features.petstore.AddAPetToThePetStoreTest)
3525 DEBUG n.s.core.photography.Darkroom: Closing darkroom
3526 INFO  net.serenitybdd.core.Serenity:
        __    _____ _____ ____ _____   ____   _    ____  ____  _____ ____
  _     \ \  |_   _| ____/ ___|_   _| |  _ \ / \  / ___|/ ___|| ____|  _ \
 (_)_____| |   | | |  _| \___ \ | |   | |_) / _ \ \___ \\___ \|  _| | | | |
  _|_____| |   | | | |___ ___) || |   |  __/ ___ \ ___) |___) | |___| |_| |
 (_)     | |   |_| |_____|____/ |_|   |_| /_/   \_\____/|____/|_____|____/
        /_/

TEST PASSED: Should be able to add pets to a store
----------------------------------------------------------------------------
3526 DEBUG n.s.j.r.RetryFilteringRunNotifier: Flushing notifications
3526 DEBUG n.s.core.photography.Darkroom: Closing darkroom

[YamStranger]

@dip56 It next release logging level will be returned to info, also you should use serenity.logging with VERBOSE value.

[dip56]

@YamStranger,I agree with you to move to debug log some information, like as darkroom, resize screenshots, flushing notifications or generating json, xml, html reports for each test. But general and more usual information about tests and step behaviors need to be in INFO mode. I think it's the right decision to return back.

Thank you for your excellent explanations and examples =)

[YamStranger]

@dip56 you are welcome!

[mariusph]

@YamStranger How do we set the logback in the pom ?

logback.xml

[mklist]

@YamStranger @dip56 Have been trying to get console logging working in real time with Serenity. In our project the console output is displayed only after test run completes. We use maven/Serenity junit. Have defined logback configuration file and it is being used. Does Serenity support real time console logging? If so what could be wrong in my config? Appreciate any feedback on this.

[b-sagar]

Hi @mklist , did you succeed in getting console logging working in real time with Serenity? I'm also struggling with it and wanted to know the solution.

I included logback-classic and slf4j-api maven dependencies. I was not able to get console logging in real time. Is logback configuration file needed? If yes, could you point me to some article showing it and how to use it in Serenity project?

Thank you

[wakaleo]

@b-sagar What makes you think the console output is NOT in real time?

[b-sagar]

Hi @wakaleo ,

As mentioned by @mklist , I too observed that logs being printed on the console when we execute mvn clean verify command, stop to be printed when a browser is launched, or when the test execution starts. Once test starts, no line is printed on the console, even though I have many System.out.println("message") statements in the scripts. When the browser closes (or the test finishes), all the logs are printed at once. Hence, I am searching for a solution to enable real time logging of all kind of print statements I have added in the scripts so that I get to know which milestone the test has reached. This is more necessary when a test verifies some data in backend systems like AWS, database, REST responses. As these tests do not involve any browser operations, it becomes difficult to assess where the test execution might be.

I hope you got the issue I wanted to describe. Looking forward to your response.

[wakaleo]

I don't think this is related to Serenity as such - Serenity simply logs info via slf4j, and doesn't have a specific logging functionality per se. It sounds more related to your build setup (if it is also happening with System.out as well). I have never seen this behaviour on any OS.

[ricardorlg]

which failsafe version are u using?

[b-sagar]

Hi @ricardorlg , I am using failsafe v 2.22.1 , here is the POM snippet

`

org.apache.maven.plugins

            <artifactId>maven-failsafe-plugin</artifactId>
            <version>2.22.1</version>
            <configuration>
                <includes>
                    <include>**/*Test.java</include>
                    <include>**/Test*.java</include>
                    <include>**/*TestSuite.java</include>
                    <include>**/When*.java</include>
                </includes>
                <systemPropertyVariables>
                    <webdriver.base.url>${webdriver.base.url}</webdriver.base.url>
                </systemPropertyVariables>
                <parallel>classes</parallel>
                <threadCount>${parallel.tests}</threadCount>
                <forkCount>${parallel.tests}</forkCount>
                <testFailureIgnore>true</testFailureIgnore>
            </configuration>
            <executions>
                <execution>
                    <goals>
                        <goal>integration-test</goal>
                        <goal>verify</goal>
                    </goals>
                </execution>
            </executions>
        </plugin>`

I can paste the entire POM if needed.

@wakaleo , I downloaded Serenity Cucumber 4 Starter project from git (https://github.com/serenity-bdd/serenity-cucumber4-starter) and updated/added the dependencies. I will download the project again and run it without any changes and will update you if I see same behaviour.

Thanks, Sagar

[b-sagar]

Hi @wakaleo ,

I downloaded Serenity Cucumber Starter project: https://github.com/serenity-bdd/serenity-cucumber-starter

The changes I made to the project:

1. src/test/resources/serenity.conf file was updated to turn the headless mode to off #headless.mode = true
2. Added System.out.println statements in the starter.stepdefinitions.SearchStepDefinitions class as below

public class SearchStepDefinitions {

@Given("{actor} is researching things on the internet")
public void researchingThings(Actor actor) {
    actor.wasAbleTo(NavigateTo.theWikipediaHomePage());

    for (int i = 0; i < 10; i++) {
        System.out.println(actor.getName() + " is on Webpage...");
        try {
            Thread.sleep(2000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

@When("{actor} looks up {string}")
public void searchesFor(Actor actor, String term) {
    actor.attemptsTo(LookForInformation.about(term));

    for (int i = 0; i < 10; i++) {
        System.out.println(actor.getName() + " is searching...");
        try {
            Thread.sleep(2000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

@Then("{actor} should see information about {string}")
public void should_see_information_about(Actor actor, String term) {
    actor.attemptsTo(Ensure.that(WikipediaArticle.HEADING).hasText(term));

    for (int i = 0; i < 10; i++) {
        System.out.println(actor.getName() + " is verifying...");
        try {
            Thread.sleep(2000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

}

3. Executed the tests from terminal with command mvn clean verify
4. Below log was displayed on console line by line before the browser was launched

/serenity-cucumber-starter-master$ mvn clean verify WARNING: An illegal reflective access operation has occurred WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/maven/lib/guice.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain) WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1 WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations WARNING: All illegal access operations will be denied in a future release [INFO] Scanning for projects... [INFO] [INFO] --------------< net.serenitybdd.starter:cucumber-starter >-------------- [INFO] Building Sample Serenity BDD project using Cucumber 1.0.0-SNAPSHOT [INFO] --------------------------------[ jar ]--------------------------------- [INFO] [INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ cucumber-starter --- [INFO] Deleting /home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/target [INFO] [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ cucumber-starter --- [INFO] Using 'UTF-8' encoding to copy filtered resources. [INFO] skip non existing resourceDirectory /home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/src/main/resources [INFO] [INFO] --- maven-compiler-plugin:3.8.1:compile (default-compile) @ cucumber-starter --- [INFO] Nothing to compile - all classes are up to date [INFO] [INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ cucumber-starter --- [INFO] Using 'UTF-8' encoding to copy filtered resources. [INFO] Copying 3 resources [INFO] [INFO] --- maven-compiler-plugin:3.8.1:testCompile (default-testCompile) @ cucumber-starter --- [INFO] Changes detected - recompiling the module! [INFO] Compiling 8 source files to /home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/target/test-classes [INFO] [INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ cucumber-starter --- [INFO] Tests are skipped. [INFO] [INFO] --- maven-jar-plugin:2.4:jar (default-jar) @ cucumber-starter --- [WARNING] JAR will be empty - no content was marked for inclusion! [INFO] Building jar: /home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/target/cucumber-starter-1.0.0-SNAPSHOT.jar [INFO] [INFO] --- maven-failsafe-plugin:3.0.0-M5:integration-test (default) @ cucumber-starter --- [INFO] [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- [ERROR] WARNING: An illegal reflective access operation has occurred [ERROR] WARNING: Illegal reflective access by net.thucydides.core.steps.StepInterceptor (file:/home/zml-ubt-sagarb-01/.m2/repository/net/serenity-bdd/serenity-core/2.6.0/serenity-core-2.6.0.jar) to field java.lang.reflect.Method.root [ERROR] WARNING: Please consider reporting this to the maintainers of net.thucydides.core.steps.StepInterceptor [ERROR] WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations [ERROR] WARNING: All illegal access operations will be denied in a future release

5. After above logging, the browser was launched and logging on the console stopped
6. The test continued to run on the browser as expected
7. The test completed the execution and browser was closed
8. Once browser closed, all of the below logs were printed at once on the console:

13:00:24.660 [main] INFO i.c.core.plugin.SerenityReporter - Running feature from file:///home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/src/test/resources/features/search/search_by_keyword.feature

13:00:24.852 [main] INFO -

---

 _______. _______ .______       _______ .__   __.  __  .___________.____    ____ 
/       ||   ____||   _  \     |   ____||  \ |  | |  | |           |\   \  /   / 

| (----| |__ | |_) | | |__ | \| | | |---| |----\ \/ / \ \ | __| | / | __| | . | | | | | _ _/
.----) | | | | |\ ----.| | | |\ | | | | | | |
|/ ||| | `.____||__||_| \| || || |__|

News and tutorials at http://www.serenity-bdd.info
Documentation at https://wakaleo.gitbooks.io/the-serenity-book/content/
Join the Serenity Community on Gitter: https://gitter.im/serenity-bdd/serenity-core Serenity BDD Support and Training at http://serenity-bdd.info/#/trainingandsupport

13:00:24.857 [main] INFO - Test Suite Started: Search by keyword

1 Scenarios ( 1 passed )

3 Steps ( 3 passed )

1m 9.916s

13:01:34.635 [pool-2-thread-1] INFO n.t.core.reports.ReportService - net.thucydides.core.reports.json.JSONTestOutcomeReporter@1e008f36: Generating report for test outcome: Search by keyword:Searching for a term

13:01:34.682 [pool-3-thread-1] INFO n.t.core.reports.ReportService - net.thucydides.core.reports.html.HtmlAcceptanceTestReporter@431f1eaf: Generating report for test outcome: Search by keyword:Searching for a term

13:01:35.550 [main] INFO i.c.core.plugin.SerenityReporter - Cleanup test resources for URI file:///home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/src/test/resources/features/search/search_by_keyword.feature

[INFO] Running Search by keyword

Scenario: Searching for a term # src/test/resources/features/search/search_by_keyword.feature:3 13:00:25.066 [pool-2-thread-1] INFO i.c.core.plugin.SerenityReporter - Running feature from file:///home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/src/test/resources/features/search/search_by_keyword.feature 13:00:25.155 [pool-2-thread-1] INFO -

---

| | | | / | | | / | | | /\ | \ | | | | | \ | | | | _ \ | | _ \ | | / \ | / | | | | | |) | || || |/ |_| |/ || // _\ ||\ || |_| |___/

Searching for a term(search-by-keyword;searching-for-a-term)

13:00:25.155 [pool-2-thread-1] INFO n.thucydides.core.model.TestOutcome - SetUserStory Search by keyword 13:00:25.168 [pool-2-thread-1] INFO n.thucydides.core.model.TestOutcome - SetUserStory Search by keyword 13:00:25.981 [pool-2-thread-1] INFO n.s.c.w.d.ChromeDriverProvider - Using automatically driver download 13:00:26.471 [pool-2-thread-1] INFO i.g.bonigarcia.wdm.WebDriverManager - Using chromedriver 93.0.4577.63 (resolved driver for Chrome 93) 13:00:26.480 [pool-2-thread-1] INFO i.g.bonigarcia.wdm.WebDriverManager - Exporting webdriver.chrome.driver as /home/zml-ubt-sagarb-01/.cache/selenium/chromedriver/linux64/93.0.4577.63/chromedriver 13:00:27.108 [pool-2-thread-1] INFO n.s.c.w.d.ProvideNewDriver - Instantiating driver 13:00:27.115 [pool-2-thread-1] INFO n.s.c.w.d.ProvideNewDriver - Driver capabilities: Capabilities {acceptInsecureCerts: false, autodownload: true, base.url: , browserName: chrome, driver: chrome, goog:chromeOptions: {args: [--start-maximized, --test-type, --no-sandbox, --ignore-certificate-errors, \n --disa..., --disable-default-apps, --disable-extensions-file-a..., \n --inco..., --disable-infobars,--disabl...], extensions: []}, loggingPrefs: org.openqa.selenium.logging...} Starting ChromeDriver 93.0.4577.63 (ff5c0da2ec0adeaed5550e6c7e98417dac77d98a-refs/branch-heads/4577@{#1135}) on port 13674 Only local connections are allowed. Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe. ChromeDriver was started successfully. Sep 22, 2021 1:00:27 PM org.openqa.selenium.remote.ProtocolHandshake createSession INFO: Detected dialect: W3C Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Sergey is on Webpage... Given Sergey is researching things on the internet # starter.stepdefinitions.SearchStepDefinitions.researchingThings(net.serenitybdd.screenplay.Actor) Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... Sergey is searching... When he looks up "Cucumber" # starter.stepdefinitions.SearchStepDefinitions.searchesFor(net.serenitybdd.screenplay.Actor,java.lang.String) Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Sergey is verifying... Then he should see information about "Cucumber" # starter.stepdefinitions.SearchStepDefinitions.should_see_information_about(net.serenitybdd.screenplay.Actor,java.lang.String) 13:01:33.472 [pool-2-thread-1] INFO -

---

| | | | / | | | | \ /\ / | / | | | | \ | | | | _ \ | | | / / \ _ \ _ \ | | | |) | || |_| |/ || || // _\ |__/ |/ || |/

Searching for a term

[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 69.688 s - in Search by keyword [INFO] [INFO] Results: [INFO] [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0 [INFO] [INFO] [INFO] --- serenity-maven-plugin:2.6.0:aggregate (serenity-reports) @ cucumber-starter --- [INFO] Test results for 1 tests generated in 1.7 secs in directory: file:/home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/target/site/serenity/ [INFO] ----------------------------------------- [INFO] SERENITY TESTS : SUCCESS [INFO] ----------------------------------------- [INFO] | Tests executed | 1 [INFO] | Tests passed | 1 [INFO] | Tests failed | 0 [INFO] | Tests with errors | 0 [INFO] | Tests compromised | 0 [INFO] | Tests pending | 0 [INFO] | Tests ignored/skipped | 0 [INFO] ------------------------ | -------------- [INFO] | Total Duration | 1m 8s [INFO] | Fastest test took | 1m 8s [INFO] | Slowest test took | 1m 8s [INFO] ----------------------------------------- [INFO] [INFO] SERENITY REPORTS [INFO] - Full Report: file:///home/zml-ubt-sagarb-01/ZiMetrics/Automation/serenity-cucumber-starter-master/target/site/serenity/index.html [INFO] [INFO] --- maven-failsafe-plugin:3.0.0-M5:verify (default) @ cucumber-starter --- [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 01:22 min [INFO] Finished at: 2021-09-22T13:01:38+05:30 [INFO] ------------------------------------------------------------------------

8. Please let me know if the issue description seems detailed.
9. I would try to see if I can record the screen somehow...
10. Below is the environment:
11. Ubuntu 18.04.6 LTS
12. IntelliJ IDEA 2021.2.2 (Community Edition) Build #IC-212.5284.40, built on September 14, 2021
13. Maven bundled into IntelliJ v3.6.3
14. Java openjdk 11.0.11 2021-04-20

Thanks, Sagar

[wakaleo]

I can't reproduce this behaviour - console output is normally written as it happens. I suspect it might be something to do with either your maven build or possibly your slf4j config.

[b-sagar]

Hi @wakaleo ,

Was your console output being logged in usual way even after you updated the starter.stepdefinitions.SearchStepDefinitions file with waits like I did..?

Can't really figure out what's wrong with my config. I just made two changes to the project as mentioned in above comment. I tried removing below logback dependency, but no luck `

ch.qos.logback

        <artifactId>logback-classic</artifactId>
        <version>1.0.13</version>
    </dependency>`

Will try using external maven (and not the one bundled with IntelliJ) and see if it makes any difference. Will post the update. Appreciate your prompt response. Thank you

[b-sagar]

[recording removed]

Hi @wakaleo , Please find the recording of the test execution. I executed it with external maven installation this time. We could see how logging halted when test was about to start ( or when browser launched)

The System.out.println statements were not logged when the test moved to next steps on UI After test completed, all the statements were logged at once.

Please suggest what could be the issue. -- Sagar

[wakaleo]

I really have no explanation or idea what this could be due to. I use real-time console output all the time to monitor long-running tests, and I have never come across this behaviour. If it is also happening with System.out, I suspect it might be an OS or JVM issue, rather than an slf4j one.

[ricardorlg]

the problem is due to parallel execution, if u remove the parallel configuration from failsafe plugin, u are now going to see the logs in real-time

[b-sagar]

Hi @ricardorlg , @wakaleo ,

I tried to execute the tests by commenting <parallel></parallel> nodes from <configuration></configuration> available with maven failsafe plugin. However, the result was similar to what I have added in above recording.

Later, I moved ahead and commented entire mavan failsafe plugin and executed the test from command line using maven surefire plugin with command mvn -Dtest=CucumberTestSuite test, but no luck.

Attached is how the POM.xml section looks now pom.txt

So there are three changes in total in Cucumber Starter project (https://github.com/serenity-bdd/serenity-cucumber-starter)

1. src/test/resources/serenity.conf file was updated to turn the headless mode to off #headless.mode = true
2. System.out.println statements added in the starter.stepdefinitions.SearchStepDefinitions class
3. and, updated POM to remove failsafe plugin.

Really clueless on the logging not printing in parallel to execution. Maybe I will have to continue with same logging process. Thank you for prompt responses. I really appreciate your help.

Will keep posted if I am able to solve the problem.

[ricardorlg]

use failsafe 2.22.2.

[b-sagar]

Hi @wakaleo , @ricardorlg

I downgraded the maven-failsafe-plugin version to 2.22.2, however it was not found by Maven. Hence tried downgrading to 2.22.1 and plugin version was resolved. The tags were commented. Executed the test and observed logs being printed on console real-time..

It worked. The recording can be seen. Thank you for all the help and patiently listening to the issue. Really appreciate.

[recording removed]

[ricardorlg]

great, when running tests in parallel, u are not going to see real-time logging, because all threads share the same terminal, so it's impossible to make real-time logging.