Junit5: Test tree printer emits extraneous characters

[smoyer64]

Overview

The test tree printer emits extraneous characters when an Extension uses the ExtensionContext.publishReportEntry() method. The sample code below exhibits this problems when added to the documentation examples and included in a test via @ExtendWith:

import org.junit.jupiter.api.extension.BeforeTestExecutionCallback;
import org.junit.jupiter.api.extension.TestExtensionContext;

public class ReportPublishingExtension implements BeforeTestExecutionCallback {

    @Override
    public void beforeTestExecution(TestExtensionContext context) throws Exception {
        context.publishReportEntry("ReportPublishingExtension", "Outputs a report entry");
    }

}



import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;

@ExtendWith(ReportPublishingExtension.class)
public class ReportPublishingDemo {

    @Test
    public void example() {

    }

}

In this case, the output contains the following snippet:

│  ├─ AssertionsDemo
│  │  ├─ groupedAssertions() ✔
│  │  ├─ exceptionTesting() ✔
│  │  ├─ standardAssertions() ✔
│  │  ├─ timeoutNotExceeded() ✔
│  │  ├─ timeoutNotExceededWithResult() ✔formTest
│  │  ├─ timeoutNotExceededWithMethod() ✔
│  │  ├─ timeoutExceeded() ✔
│  │  ├─ timeoutExceededWithPreemptiveTermination() ✔

Note the extra formTest next to the check indicating that the timeoutNotExceededWithResult() test has passed. In the ANSI output, the text is shown in bright white and is always some portion of the phrase "platformTest".

• (X) Bug report. This problem looks like there's information sticking around in a buffer somewhere. If there are multiple extensions that publish report entries, of even if one Extension publishes report entries multiple times, there will be one or more places where the extra characters are emitted. The position of the extra characters in the rendered tree does not appear to be related to when the report entry is published.

Deliverables

• [ ] Allow extensions to publish report entries without extraneous content being printed in the tree.

[sormuras]

Good catch. Are you using more than one thread for execution? Ah, you do: timeout...-assertion do thread-y things. Does it also happend, when just execute _plain_ in-thread assertions?

[smoyer64]

Hmm ... I don't know as I just added the two classes above to the documentation:junitPlatformTests. I added @Disabled to the top-of-class for AssertionsDemo, TimingExtensionTests and my as yet unmerged TimeoutJupiterDemo and the problem still happens. I'm pretty sure that eliminates all the places where a thread is spawned to watchdog a test's run-time. I've got timing included in other tests but it's simply System.nanoTime() which will not require another thread.

One additional clue, it seems as if the more times report entries are written via an Extension, the more times there is cruft in the output. Here's an example of the output with the assertTimeoutPreemptively() methods all @Disabled:

│  ├─ StopwatchJupiterDemo
│  │  │   ReportEntry [timestamp = 2017-02-19T13:30:08.931, Method execution time (in uS) = '299']
│  │  ├─ succeeds(TestReporter) ✔
│  │  │   ReportEntry [timestamp = 2017-02-19T13:30:08.932, Method execution time (in uS) = '204']
│  │  ├─ fails() ✘ Time a failing test
│  │  │   ReportEntry [timestamp = 2017-02-19T13:30:08.936, Method execution time (in uS) = '252']
│  │  ├─ skips() ■ Assumption failed: assumption is not true
│  │  │   ReportEntry [timestamp = 2017-02-19T13:30:09.742, Method execution time (in uS) = '802246']
│  │  ├─ performanceTest(Stopwatch) ✔PlatformTest

[sormuras]

│  │  ├─ timeoutNotExceededWithResult() ✔formTest
│  │  ├─ performanceTest(Stopwatch) ✔PlatformTest

Right-padded to column 50? How is that possible... by chance? Can you please rename performanceTest(Stopwatch) to t(...) and share the result?

[smoyer64]

I have no idea how that's possible ... 0x50 is 80 so is it possible someone tried to truncate to 80 columns and got the wrong base? In any case, I didn't rename the test but rather copied it while giving it a shorter and a longer name. I think you nailed it:

│  ├─ StopwatchJupiterDemo
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:03.446, Method execution time (in uS) = '802092']
│  │  ├─ perfTest(Stopwatch) ✔n:junitPlatformTest
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:04.249, Method execution time (in uS) = '800823']
│  │  ├─ performanceAssertingTest(Stopwatch) ✔est
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:04.252, Method execution time (in uS) = '452']
│  │  ├─ succeeds(TestReporter) ✔
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:04.255, Method execution time (in uS) = '362']
│  │  ├─ fails() ✘ Time a failing test
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:04.258, Method execution time (in uS) = '239']
│  │  ├─ skips() ■ Assumption failed: assumption is not true
│  │  │   ReportEntry [timestamp = 2017-02-19T15:58:05.061, Method execution time (in uS) = '800861']
│  │  ├─ performanceTest(Stopwatch) ✔PlatformTest

It sure looks like something is reusing a buffer somewhere though! And apparently I can eliminate this problem by giving my tests sufficiently long names ;)

[smoyer64]

I thought that I should actually make sure a really long name works okay ... here's one more test added to those above:

│  │  │   ReportEntry [timestamp = 2017-02-19T16:03:55.046, Method execution time (in uS) = '800993']
│  │  ├─ performanceAssertingTestWithHyperLongName(Stopwatch) ✔

As you can see, the name itself is longer than 50 characters and does not get truncated.

[sormuras]

Hm, why doesn't it happen to:

│  │  ├─ succeeds(TestReporter) ✔
│  │  ├─ fails() ✘ Time a failing test

?

[sormuras]

Ah! n:junitPlatformTest ... the double point indicates that some Gradle task is getting between us.

[smoyer64]

I had assumed that the "n" was the last character of documentation but didn't think about Gradle being multi-threaded (and contending).

[sormuras]

In the ANSI output, the text is shown in bright white and is always some portion of the phrase "platformTest".

The bright white also points to Gradle console output.

I tend to close this issue as: won't fix

[smoyer64]

The bright white also points to Gradle console output.

I haven't tried this via the CLI ... since both use the console runner I simply expected the same behavior and it's easy (within the junit5 project) to run the tests via Gradle. I am a little curious why this only seems to happen when a ReportEntry is emitted from an Extension and not when a ReportEntry is emitted by a test.

[sormuras]

With #711 merged, the entire tree is printed in a single "print" call. That prevents Gradle output to mix with the test plan tree.

Closing this issue for now.

[sbrannen]

So, can we assign a release version (milestone) or pick an appropriate _status_ label?

[smoyer64]

A quick note to say that the test tree printer's output looks fantastic! I'm going to rerun the examples I'm working on for the JUnit 4 compatibility section of the users manual and we (Penn State University) will update our slide deck next time we're going to present on JUnit 5.

Thanks!