Gradle 4.6: junit5 integration ignores exceptionFormat

[mvysny]

I have the following in my build.gradle file:

test {
    useJUnitPlatform()
    testLogging {
        // to see the exceptions of failed tests in Travis-CI console.
        exceptionFormat = 'full'
    }
}

Since I'm using Travis-CI, I do not have access to the text report html file. Therefore, I would like to see the stacktraces of failed tests in the console. However, Gradle seems to ignore the exceptionFormat parameter and does not print the stacktraces into the console:

> Task :test 

com.github.vokorm.DaoTest > fails if there are ten matching entities FAILED
    java.lang.AssertionError: foo

com.github.vokorm.DaoTest > fails if there are ten matching entities FAILED
    java.lang.AssertionError: foo

59 tests completed, 2 failed


FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':test'.
> There were failing tests. See the report at: file:///home/mavi/work/my/vok/vok-orm/build/reports/tests/test/index.html

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output. Run with --scan to get full insights.

Expected Behavior

The full stacktraces of failed tests should be printed into the console.

Current Behavior

Only the exception type and the message is printed. That unfortunately doesn't give insight to the root of the issue.

Context

Since I'm using Travis-CI, I do not have access to the text report html file. Therefore, I would like to see the stacktraces of failed tests in the console.

Steps to Reproduce (for bugs)

Create a junit5-based project with one failing tests; then configure Gradle with:

test {
    useJUnitPlatform()
    testLogging {
        // to see the exceptions of failed tests in Travis-CI console.
        exceptionFormat = 'full'
    }
}

Your Environment

java -version
openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-0ubuntu0.17.10.2-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

[blindpirate]

Thanks for reporting, but I tried with the procedure you mentioned and did observe the stacktrace. Here's what I tried:

package org.gradle;

class JupiterTest {
    @org.junit.jupiter.api.Test public void test(){
         org.junit.jupiter.api.Assertions.assertTrue(false);
    }
}

And my console displays:

org.gradle.JupiterTest > test() FAILED
    org.opentest4j.AssertionFailedError: expected: <true> but was: <false>
        at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:36)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:42)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:37)
        at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:115)
        at org.gradle.JupiterTest.test(JupiterTest.java:5)

1 test completed, 1 failed

It would be great if you can provide a minimum sample project. Thanks!

[mvysny]

Thank you very much for investigating! You're right - it works properly for junit-jupiter-engine, however it seems to cut off the stack trace for a custom testing engine I've been designing. Please find the steps to reproduce the issue below:

1. git clone https://github.com/mvysny/dynatest
2. Edit the SanityTest.kt file and make the first function named simple() fail:

    @Test
    fun simple() {
        expect(2) { 1 }
    }

3. Then please edit TestUtilsTest.kt and make the first test fail:

        test("throwing expected exception succeeds") {
            expect(2) { 1 }
        }

When I now run ./gradlew, I can see the following output:

> Task :test FAILED

com.github.mvysny.dynatest.TestUtilsTest > throwing expected exception succeeds FAILED
    java.lang.AssertionError: Expected <2>, actual <1>.

com.github.mvysny.dynatest.SanityTest > simple() FAILED
    java.lang.AssertionError: Expected <2>, actual <1>.
        at kotlin.test.DefaultAsserter.fail(DefaultAsserter.kt:12)
        at kotlin.test.Asserter$DefaultImpls.assertTrue(Assertions.kt:157)
        at kotlin.test.DefaultAsserter.assertTrue(DefaultAsserter.kt:7)
        at kotlin.test.Asserter$DefaultImpls.assertEquals(Assertions.kt:176)
        at kotlin.test.DefaultAsserter.assertEquals(DefaultAsserter.kt:7)
        at kotlin.test.AssertionsKt__AssertionsKt.assertEquals(Assertions.kt:59)
        at kotlin.test.AssertionsKt.assertEquals(Unknown Source)
        at kotlin.test.AssertionsKt__AssertionsKt.assertEquals$default(Assertions.kt:58)
        at kotlin.test.AssertionsKt.assertEquals$default(Unknown Source)
        at kotlin.test.AssertionsKt__AssertionsKt.expect(Assertions.kt:105)
        at kotlin.test.AssertionsKt.expect(Unknown Source)
        at com.github.mvysny.dynatest.SanityTest.simple(SanityTest.kt:14)

83 tests completed, 2 failed

The JUnit-based stacktraces are properly visible, yet the stacktraces reported by the custom testing tool are cut off.

[blindpirate]

I'm sorry but I can't reproduce it with the procedure you described. I did as you said and only get:

$ gradleDev test

> Task :test 

com.github.mvysny.dynatest.SanityTest > simple() FAILED
    java.lang.AssertionError at SanityTest.kt:10

4 tests completed, 1 failed

Can you checkout a branch which has everything and doesn't need me to manually edit here and there?

[mvysny]

Thanks, sure! I have created the gradle4681 branch which, when I run it with the gradle-4.6 embedded in the repo with ./gradlew, will print the following:

$ ./gradlew

> Task :test FAILED

com.github.mvysny.dynatest.TestUtilsTest > throwing expected exception succeeds FAILED
    java.lang.RuntimeException: This will not print stacktrace

com.github.mvysny.dynatest.SanityTest > simple() FAILED
    java.lang.RuntimeException: This will print correct stacktrace
        at com.github.mvysny.dynatest.SanityTest.simple(SanityTest.kt:14)

83 tests completed, 2 failed

[blindpirate]

Thanks, now I see this behavior. After a little investigation, I found the root cause.

For the JUnit-based test, Gradle gets an exception like this:

com.github.mvysny.dynatest.SanityTest.simple(SanityTest.kt:14)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:436)
org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:115)
org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:170)

...Too long to display...

It's too long so Gradle has to truncate it, but from where? Gradle knows the current test method is com.github.mvysny.dynatest.SanityTest.simple(), so it can simple truncate all stacktraces below first line. That's what you see finally:

com.github.mvysny.dynatest.SanityTest > simple() FAILED
    java.lang.RuntimeException: This will print correct stacktrace
        at com.github.mvysny.dynatest.SanityTest.simple(SanityTest.kt:14)

However, for your custom engine, the exception looks like this:

com.github.mvysny.dynatest.TestUtilsTest$1$1$1.invoke(TestUtilsTest.kt:12)
com.github.mvysny.dynatest.TestUtilsTest$1$1$1.invoke(TestUtilsTest.kt:9)
com.github.mvysny.dynatest.DynaTestEngine$execute$1$1.invoke(DynaTestEngine.kt:81)
com.github.mvysny.dynatest.DynaTestEngine$execute$1$1.invoke(DynaTestEngine.kt:20)
com.github.mvysny.dynatest.DynaNodeTestDescriptor.runBlock(DynaTestEngine.kt:184)
com.github.mvysny.dynatest.DynaTestEngine$execute$1.invoke(DynaTestEngine.kt:81)
com.github.mvysny.dynatest.DynaTestEngine$execute$2.invoke(DynaTestEngine.kt:104)
com.github.mvysny.dynatest.DynaTestEngine$execute$2.invoke(DynaTestEngine.kt:101)
com.github.mvysny.dynatest.DynaTestEngine$execute$2.invoke(DynaTestEngine.kt:101)
com.github.mvysny.dynatest.DynaTestEngine$execute$2.invoke(DynaTestEngine.kt:101)
com.github.mvysny.dynatest.DynaTestEngine.execute(DynaTestEngine.kt:115)

...

It's too hard for Gradle to decide where to start truncating, so it has to truncate all. That's why you see

com.github.mvysny.dynatest.TestUtilsTest > throwing expected exception succeeds FAILED
    java.lang.RuntimeException: This will not print stacktrace

I think for a while and failed to think of a solution for this. For the latter case, what's your expected behavior? Where do you want it to be truncated?

[mvysny]

I understand that there is lot of thought put into Gradle's code and hence I'm hesitant to offer my advice on the matter. Yet, here I go :)

I am using Travis-CI to test my projects. When a test fails, for me the quickest way to learn the cause of the failure is to see the stacktrace of the exception thrown. Typically one reads the build/test-results/test/TEST-*.xml files to learn the stacktrace, but that's impossible with Travis-CI since there is no access to the filesystem. Therefore I have configured Gradle to display the stack traces of failed tests, by the means of setting exceptionFormat="FULL". I was expecting at least partial stack traces, but to my surprise I have found the stack traces missing in the console. I therefore believe that showing no stack trace is the most confusing behaviour, hence this bug report.

Since I have specifically configured Gradle to show full exception format, showing a full untruncated stack trace is therefore expected and acceptable for me, because it enables me to find the source of the bug. Since there are at most a handful of tests failing in the most common case, full stack traces will not clutter up the console output badly.

Of course, if Gradle is smart enough to chop out pieces of stack trace that are unimportant, that's even better. However, if it is not possible to do so, I find it perfectly acceptable for Gradle to fall back and show the full stack trace.

Now for the truncating algorithm: I am hesitant to give advice since I haven't thought about the algorithm that much. I was thinking of the following algorithm:

• If Gradle knows which method is being tested and it is able to find it in the stack trace, chop the stacktrace there (the SanityTest.simple() method in the above example).
• If we do not know the method or we can't match it to stack trace frame, and we know the class being tested, find the class and chop the stacktrace there. For example TestUtilsTest would chop off the stack trace to only contain two lines:

com.github.mvysny.dynatest.TestUtilsTest$1$1$1.invoke(TestUtilsTest.kt:12)
com.github.mvysny.dynatest.TestUtilsTest$1$1$1.invoke(TestUtilsTest.kt:9)

• If that was not possible, fall back and show the full stack trace.

The important thing is that the algorithm should fall back to show a full stack trace instead of an empty one.

[blindpirate]

Thanks for your thought! I think that's pretty reasonable. However we might not have enough capacity to support this, would you like to provide a pull request? The related logic is in FullExceptionFormatter, ClassMethodNameStackTraceSpec and TruncatedStackTraceSpec. No pressure, it's totally up to you.

[blindpirate]

If we do not know the method or we can't match it to stack trace frame, and we know the class being tested, find the class and chop the stacktrace there. For example TestUtilsTest would chop off the stack trace to only contain two lines

P.S. in the case you provided, the test descriptor's class name (TestDescriptor.getSource().getClassName()) is com.github.mvysny.dynatest.TestUtilsTest but stacktrace element is

So I guess it's not easy to "know the class being tested".

[mvysny]

Thank you very much, and I apologize I was unable to find time to fix this myself.

[blindpirate]

Not at all! Thanks for the reporting! Please try our 4.7RC1 next week when it comes out to see if it solves this problem.

[mvysny]

Just tested with Gradle 4.7-rc-1 and the bug is indeed fixed!

com.github.mvysny.dynatest.TestUtilsTest > throwing expected exception succeeds FAILED
    java.lang.AssertionError: Expected <2>, actual <1>.
        at kotlin.test.DefaultAsserter.fail(DefaultAsserter.kt:12)
        at kotlin.test.Asserter$DefaultImpls.assertTrue(Assertions.kt:157)
        at kotlin.test.DefaultAsserter.assertTrue(DefaultAsserter.kt:7)
        at kotlin.test.Asserter$DefaultImpls.assertEquals(Assertions.kt:176)
        at kotlin.test.DefaultAsserter.assertEquals(DefaultAsserter.kt:7)
        at kotlin.test.AssertionsKt__AssertionsKt.assertEquals(Assertions.kt:59)
        at kotlin.test.AssertionsKt.assertEquals(Unknown Source)
        at kotlin.test.AssertionsKt__AssertionsKt.assertEquals$default(Assertions.kt:58)
        at kotlin.test.AssertionsKt.assertEquals$default(Unknown Source)
        at kotlin.test.AssertionsKt__AssertionsKt.expect(Assertions.kt:105)
        at kotlin.test.AssertionsKt.expect(Unknown Source)
        at com.github.mvysny.dynatest.TestUtilsTest$1$5.invoke(TestUtilsTest.kt:126)
        at com.github.mvysny.dynatest.TestUtilsTest$1$5.invoke(TestUtilsTest.kt:9)

Awesome, thank you guys :) The stack trace is truncated exactly at TestUtilsTest and the truncation code works properly in spite of those $1$5 anonymous classes.

[blindpirate]

Thanks @mvysny !