Bug 64836

Summary: junitlaucher poor summary
Product: Ant Reporter: Filipe Silva <filipe.silva>
Component: Optional TasksAssignee: Ant Notifications List <notifications>
Status: RESOLVED FIXED    
Severity: minor CC: dominik.stadler, kiwiwings
Priority: P2    
Version: 1.10.9   
Target Milestone: 1.10.10   
Hardware: PC   
OS: Linux   

Description Filipe Silva 2020-10-21 11:25:02 UTC
The summary of a junitlaucher task looks like this:

[junitlauncher] 
[junitlauncher] Test run finished after 5103 ms
[junitlauncher] [         2 containers found      ]
[junitlauncher] [         0 containers skipped    ]
[junitlauncher] [         2 containers started    ]
[junitlauncher] [         0 containers aborted    ]
[junitlauncher] [         2 containers successful ]
[junitlauncher] [         0 containers failed     ]
[junitlauncher] [         1 tests found           ]
[junitlauncher] [         0 tests skipped         ]
[junitlauncher] [         1 tests started         ]
[junitlauncher] [         0 tests aborted         ]
[junitlauncher] [         1 tests successful      ]
[junitlauncher] [         0 tests failed          ]
[junitlauncher] 
[junitlauncher] 
[junitlauncher] Test run finished after 99 ms
[junitlauncher] [         2 containers found      ]
[junitlauncher] [         0 containers skipped    ]
[junitlauncher] [         2 containers started    ]
[junitlauncher] [         0 containers aborted    ]
[junitlauncher] [         2 containers successful ]
[junitlauncher] [         0 containers failed     ]
[junitlauncher] [         6 tests found           ]
[junitlauncher] [         3 tests skipped         ]
[junitlauncher] [         3 tests started         ]
[junitlauncher] [         0 tests aborted         ]
[junitlauncher] [         3 tests successful      ]
[junitlauncher] [         0 tests failed          ]
[junitlauncher] 

(...)

Which is pretty useless if the classes containing the tests aren't shown.

This is how I'm running the task:

<junitlauncher haltOnFailure="false" printSummary="true" failureProperty="junit.fail">
    <classpath refid="build.classpath" />

    <testclasses outputdir="${junit.results}">
        <fileset dir="${build.dir}">
            <include name="**/*Test.class" />
        </fileset>
        <fork>
            <jvmarg value="-Xmx1024m" />
            <syspropertyset refid="junit.system.properties" />
        </fork>
        <listener type="legacy-xml" sendSysOut="true" sendSysErr="true" />
        <listener type="legacy-plain" sendSysOut="true" sendSysErr="true" />
    </testclasses>
</junitlauncher>


Can this information be added or am I missing something?

Thanks
Comment 1 Andreas Beeker 2020-12-22 20:31:09 UTC
A kind of workaround, but outputs the results only after the tests are finished:

https://www.selikoff.net/2018/07/28/ant-and-junit-5-outputting-test-duration-and-failure-to-the-log/
Comment 2 Jaikiran Pai 2020-12-23 01:20:33 UTC
Hello Filipe and Andreas,

This output/summary:

> [junitlauncher] 
> [junitlauncher] Test run finished after 5103 ms
> [junitlauncher] [         2 containers found      ]
> [junitlauncher] [         0 containers skipped    ]
> [junitlauncher] [         2 containers started    ]
> ...

As noted in the documentation of the junitlauncher task[1] this summary is generated by the JUnit 5 platform itself and not by Ant's junitlauncher task. I don't know if the JUnit 5 team has plans to improve this. They accept user suggestions for things like this at their github repo https://github.com/junit-team/junit5/

[1] https://ant.apache.org/manual/Tasks/junitlauncher.html
Comment 3 Jaikiran Pai 2020-12-23 01:32:49 UTC
I just read that linked blog article that Andreas pointed to. So I think the main missing feature in junitlauncher task (as compared to Ant's junit task) is this:

> With JUnit 4 and Ant, you got output that looked list this for each test run.
> In the console. Real time while the build was running. 
> This was really useful.
> [junit] Running com.javaranch.jforum.MissingHeadTagTest
> [junit] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.685 sec

The real time nature of printing which test is being run I guess is what you are looking for as a summary (while the tests are still running). We currently write out these details to a file (if you use the legacy-plain listener), but it looks like users want to see it on the console as well. I think that's a useful feature to add. I'll take a look at it and see what we can do here.
Comment 4 Filipe Silva 2021-01-06 09:59:46 UTC
Hi Jaikiran,

Exactly. That is the information that is missing, otherwise we can't know to what test set/class each one of the reports pertain.

I ended up implementing the listener suggested in the article Andreas pointed out with some changes/improvements that allow to see the output while the tests are running, as I mentioned in a comment, since the original version only printed the report after all tests have run.

Thanks for looking into this.
Comment 5 Andreas Beeker 2021-01-09 19:36:22 UTC
> with some changes/improvements that allow to see the output while the tests are running
@Filipe: how do you "tail -f" to ants stdout?

Currently our travis build timeouts after 10 min. of no-output, as we have pretty long integration tests.
Comment 6 Filipe Silva 2021-01-11 17:15:27 UTC
Hi Andreas,

I just took a copy of `System.out` before it gets replaced inside other listeners.

Let me share my code with you:

```
import java.io.PrintStream;
import java.time.Duration;
import java.time.Instant;
import java.util.Optional;
import java.util.concurrent.atomic.AtomicInteger;

import org.junit.platform.engine.TestExecutionResult;
import org.junit.platform.launcher.TestExecutionListener;
import org.junit.platform.launcher.TestIdentifier;

public class JUnitSummary implements TestExecutionListener {
    private AtomicInteger numSkippedInTestSet = new AtomicInteger();
    private AtomicInteger numAbortedInTestSet = new AtomicInteger();
    private AtomicInteger numSucceededInTestSet = new AtomicInteger();
    private AtomicInteger numFailedInTestSet = new AtomicInteger();
    private Instant testSetStartTime;

    PrintStream out = null;

    public JUnitSummary() {
        this.out = System.out;
    }

    private void resetCountsForNewTestSet() {
        this.numSkippedInTestSet.set(0);
        this.numAbortedInTestSet.set(0);
        this.numSucceededInTestSet.set(0);
        this.numFailedInTestSet.set(0);
        this.testSetStartTime = Instant.now();
    }

    @Override
    public void executionStarted(TestIdentifier testIdentifier) {
        Optional<String> parentId = testIdentifier.getParentId();
        if (parentId.isPresent() && parentId.get().indexOf('/') < 0) {
            println("\nRunning " + testIdentifier.getLegacyReportingName());
            resetCountsForNewTestSet();
        }
    }

    @Override
    public void executionSkipped(TestIdentifier testIdentifier, String reason) {
        this.numSkippedInTestSet.incrementAndGet();
    }

    @Override
    public void executionFinished(TestIdentifier testIdentifier, TestExecutionResult testExecutionResult) {
        Optional<String> parentId = testIdentifier.getParentId();
        if (parentId.isPresent() && parentId.get().indexOf('/') < 0) {
            int totalTestsInClass = this.numSucceededInTestSet.get() + this.numAbortedInTestSet.get() + this.numFailedInTestSet.get()
                    + this.numSkippedInTestSet.get();
            Duration duration = Duration.between(this.testSetStartTime, Instant.now());
            double numSeconds = (double) duration.toMillis() / 1_000;
            String summary = String.format("Tests run: %d, Failures: %d, Aborted: %d, Skipped: %d, Time elapsed: %f sec", totalTestsInClass,
                    this.numFailedInTestSet.get(), this.numAbortedInTestSet.get(), this.numSkippedInTestSet.get(), numSeconds);
            println(summary);
        } else if (testIdentifier.isTest()) {
            switch (testExecutionResult.getStatus()) {
                case SUCCESSFUL:
                    this.numSucceededInTestSet.incrementAndGet();
                    break;
                case ABORTED:
                    println("   Aborted: " + testIdentifier.getDisplayName());
                    this.numAbortedInTestSet.incrementAndGet();
                    break;
                case FAILED:
                    println("   Failed: " + testIdentifier.getDisplayName());
                    this.numFailedInTestSet.incrementAndGet();
                    break;
            }
        }
    }

    private void println(String str) {
        this.out.println(str);
    }
}
```

And then I use it like this in ant:

```
<junitlauncher haltOnFailure="false" printSummary="true">
    <testclasses>
        <fileset dir="...">
            <include name="**/*Test.class" />
        </fileset>
        <listener classname="JUnitSummary" />
        <listener type="legacy-xml" sendSysOut="true" sendSysErr="true" />
        <listener type="legacy-plain" sendSysOut="true" sendSysErr="true" />
    </testclasses>
</junitlauncher>
```
Comment 7 Jaikiran Pai 2021-01-15 14:22:32 UTC
I've just pushed a commit to upstream master branch which improves the summary reporting in "junitlauncher" task. If the printSummary attribute is set to true, then this task now prints out (to System.out) instantly (instead of waiting for the test plan to complete) the test summary. This summary is now similar to what the previous "junit" task generates.

We have nightly Ant builds available. This change should be available in the next nightly build. They are available at https://ci-builds.apache.org/job/Ant/job/Ant_Nightly/lastSuccessfulBuild/artifact/distribution/

Could either of you download this nightly build and give it a try against your projects and let us know how it goes?
Comment 8 Filipe Silva 2021-01-23 19:22:25 UTC
Hi Jaikiran,

Finally I had some time to experiment your build.

I see you made the new summary pretty much like the old one from the junit task with only a few differences in the fields displayed. It seems to be working fine but I have a few remarks:

* The new summary is currently showing the fields "Tests run", "Failures", "Skipped" and "Time elapsed". Can't you also include "Aborted"? I think you should be able to extract it form the Junit 5 summary. E.g.:

    [junitlauncher] Tests run: 6, Failures: 0, Aborted: 0, Skipped: 0, Time elapsed: 0,007 sec
  
* Your "Time elapsed" information formatted with a dot (.) as decimal separator. Can't you make it region based? In my region it should be formatted with a comma (,).

* Indentation. I don't know if you can do something about this. Currently it is printing this:

test:
    [mkdir] Created dir: /home/...
     [echo] Running my tests with jvm '/usr/lib/jvm/jdk-8/bin/java'
[junitlauncher] Tests run: 0, Failures: 0, Skipped: 0, Time elapsed: 0.05 sec
[junitlauncher] Running test.MyTest1
[junitlauncher] Tests run: 18, Failures: 0, Skipped: 0, Time elapsed: 132.978 sec
...

  While a similar run with the old junit task prints this:

test:
    [mkdir] Created dir: /home/...
     [echo] Running my tests jvm '/usr/lib/jvm/jdk-5/bin/java'
    [junit] Running test.MyTest1
    [junit] Tests run: 10, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4,587 sec
...
  
  I don't know if this is because the word "junitlauncher" is too long for the reserved space (it seems that prefixes are right aligned at column 11) or something else. It just doesn't look that nice.

* I don't know if you see this too, but in my project there's always an empty container being executed first. Using your build, this is the first [junitlaucher] line:

[junitlauncher] Tests run: 0, Failures: 0, Skipped: 0, Time elapsed: 0.05 sec

  I know this is not exclusive to your build because previously I had the following before running and showing the containers that actually have tests on them:

[junitlauncher] 
[junitlauncher] Test run finished after 52 ms
[junitlauncher] [         1 containers found      ]
[junitlauncher] [         0 containers skipped    ]
[junitlauncher] [         1 containers started    ]
[junitlauncher] [         0 containers aborted    ]
[junitlauncher] [         1 containers successful ]
[junitlauncher] [         0 containers failed     ]
[junitlauncher] [         0 tests found           ]
[junitlauncher] [         0 tests skipped         ]
[junitlauncher] [         0 tests started         ]
[junitlauncher] [         0 tests aborted         ]
[junitlauncher] [         0 tests successful      ]
[junitlauncher] [         0 tests failed          ]

  Perhaps this is caused by the way I have my tests organized, but I haven't figured out why, yet. I just know that there's no class name associated with this container. 

  It would be nice if you could do something about this "empty" line too.


That's all from me at the moment.

Many thanks of your great work!
Comment 9 Jaikiran Pai 2021-01-24 14:34:24 UTC
Hello Filipe,

Thank you for giving the build a try and thank you for reporting back with your feedback.

> Can't you also include "Aborted"? I think you should be able to extract it form the Junit 5 summary. 

Done. It now shows aborted count too.


> Your "Time elapsed" information formatted with a dot (.) as decimal separator. Can't you make it region based? In my region it should be formatted with a comma (,)

This one is done too.

> I don't know if you see this too, but in my project there's always an empty container being executed first. 

I have pushed a commit which I think should fix this and should no longer show this in the summary output. I don't have a way to reproduce this or test this though.

> Indentation. I don't know if you can do something about this.

I haven't looked into this one and I don't think I'll be able to get to this anytime soon. Given the nature of it, I think it's not that big a deal, IMO.


If you get a chance please do test the latest nightly build and see how it goes.
Comment 10 Filipe Silva 2021-01-26 00:27:52 UTC
Hi Jaikiran,

It's looking good.

Thank you very much.