Question on the output of test failures. The stack...

# kotest

[taer]

Question on the output of test failures. The stack traces I get are pretty much useless sometimes. Is there something I'm doing incorrect? Will post in thread

[taer]

This is a stack trace I have:

[taer]

java.lang.AssertionError: <null> should not equal <null>
	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:91)
	at kotlinx.coroutines.CoroutineScopeKt.coroutineScope(CoroutineScope.kt:194)
	at io.kotest.core.internal.TestCaseExecutor.executeInScope(TestCaseExecutor.kt:252)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1$1.invokeSuspend(TestCaseExecutor.kt:227)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1$1.invoke(TestCaseExecutor.kt)
	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturnIgnoreTimeout(Undispatched.kt:102)
	at kotlinx.coroutines.TimeoutKt.setupTimeout(Timeout.kt:120)
	at kotlinx.coroutines.TimeoutKt.withTimeout(Timeout.kt:37)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1.invokeSuspend(TestCaseExecutor.kt:226)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1.invoke(TestCaseExecutor.kt)
	at io.kotest.engine.ExecutorExecutionContext$executeWithTimeoutInterruption$$inlined$suspendCoroutine$lambda$2.invokeSuspend(ExecutorExecutionContext.kt:56)
	at ???(Coroutine boundary.?(?)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1$1.invokeSuspend(TestCaseExecutor.kt:227)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1.invokeSuspend(TestCaseExecutor.kt:226)
	at io.kotest.core.internal.TestCaseExecutor.executeAndWait(TestCaseExecutor.kt:212)
	at io.kotest.core.internal.TestCaseExecutor.invokeTestCase(TestCaseExecutor.kt:180)
	at io.kotest.core.internal.TestCaseExecutor.executeActiveTest(TestCaseExecutor.kt:149)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1$1.invokeSuspend(TestCaseExecutor.kt:87)
	at io.kotest.core.internal.TestCaseExecutor.executeIfActive(TestCaseExecutor.kt:113)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1.invokeSuspend(TestCaseExecutor.kt:87)
	at io.kotest.core.internal.TestCaseExecutor.execute(TestCaseExecutor.kt:67)
	at io.kotest.engine.runners.SingleInstanceSpecRunner.runTest(SingleInstanceSpecRunner.kt:73)
Caused by: java.lang.AssertionError: <null> should not equal <null>
	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:91)
	at kotlinx.coroutines.CoroutineScopeKt.coroutineScope(CoroutineScope.kt:194)
	at io.kotest.core.internal.TestCaseExecutor.executeInScope(TestCaseExecutor.kt:252)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1$1.invokeSuspend(TestCaseExecutor.kt:227)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1$1.invoke(TestCaseExecutor.kt)
	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturnIgnoreTimeout(Undispatched.kt:102)
	at kotlinx.coroutines.TimeoutKt.setupTimeout(Timeout.kt:120)
	at kotlinx.coroutines.TimeoutKt.withTimeout(Timeout.kt:37)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1.invokeSuspend(TestCaseExecutor.kt:226)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3$1.invoke(TestCaseExecutor.kt)
	at io.kotest.engine.ExecutorExecutionContext$executeWithTimeoutInterruption$$inlined$suspendCoroutine$lambda$2.invokeSuspend(ExecutorExecutionContext.kt:56)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:84)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at io.kotest.engine.ExecutorExecutionContext.executeWithTimeoutInterruption(ExecutorExecutionContext.kt:55)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3.invokeSuspend(TestCaseExecutor.kt:225)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1$3.invoke(TestCaseExecutor.kt)
	at io.kotest.mpp.ReplayKt.replay(replay.kt:18)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1.invokeSuspend(TestCaseExecutor.kt:220)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2$1.invoke(TestCaseExecutor.kt)
	at io.kotest.engine.ExecutorExecutionContext$executeWithTimeoutInterruption$$inlined$suspendCoroutine$lambda$2.invokeSuspend(ExecutorExecutionContext.kt:56)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:84)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at io.kotest.engine.ExecutorExecutionContext.executeWithTimeoutInterruption(ExecutorExecutionContext.kt:55)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2.invokeSuspend(TestCaseExecutor.kt:213)
	at io.kotest.core.internal.TestCaseExecutor$executeAndWait$2.invoke(TestCaseExecutor.kt)
	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturnIgnoreTimeout(Undispatched.kt:102)
	at kotlinx.coroutines.TimeoutKt.setupTimeout(Timeout.kt:120)
	at kotlinx.coroutines.TimeoutKt.withTimeout(Timeout.kt:37)
	at io.kotest.core.internal.TestCaseExecutor.executeAndWait(TestCaseExecutor.kt:212)
	at io.kotest.core.internal.TestCaseExecutor.invokeTestCase(TestCaseExecutor.kt:180)
	at io.kotest.core.internal.TestCaseExecutor.executeActiveTest(TestCaseExecutor.kt:149)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1$1.invokeSuspend(TestCaseExecutor.kt:87)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1$1.invoke(TestCaseExecutor.kt)
	at io.kotest.core.internal.TestCaseExecutor.executeIfActive(TestCaseExecutor.kt:113)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1.invokeSuspend(TestCaseExecutor.kt:87)
	at io.kotest.core.internal.TestCaseExecutor$intercept$innerExecute$1.invoke(TestCaseExecutor.kt)
	at io.kotest.core.internal.TestCaseExecutor.intercept(TestCaseExecutor.kt:101)
	at io.kotest.core.internal.TestCaseExecutor.execute(TestCaseExecutor.kt:67)
	at io.kotest.engine.runners.SingleInstanceSpecRunner.runTest(SingleInstanceSpecRunner.kt:73)
	at io.kotest.engine.runners.SingleInstanceSpecRunner$execute$2$invokeSuspend$$inlined$invoke$lambda$1.invokeSuspend(SingleInstanceSpecRunner.kt:83)
	at io.kotest.engine.runners.SingleInstanceSpecRunner$execute$2$invokeSuspend$$inlined$invoke$lambda$1.invoke(SingleInstanceSpecRunner.kt)
	at io.kotest.engine.spec.SpecRunner$runParallel$$inlined$map$lambda$2$1.invokeSuspend(SpecRunner.kt:80)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)
	at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:84)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
	at io.kotest.engine.spec.SpecRunner$runParallel$$inlined$map$lambda$2.run(SpecRunner.kt:79)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

[taer]

There's not a single line in there helping me find the assertion that failed. I think the issue is the test looks like this.

test("Data generation") {
        val generateData = store.generateData(listOf(ReferenceFields.refEnumField.id))
        assertSoftly(generateData.first().valuesList.single()) {
            id shouldBe ReferenceFields.refEnumField.id
            value.valueCase shouldBe ValueHolder.ValueCase.ENUM
            value.enum.ordinal shouldBeGreaterThan 0
            Common.TenantType.forNumber(value.enum.ordinal) shouldNotBe null
        }
    }

[taer]

The failure was obviously here Common.TenantType.forNumber(value.enum.ordinal) shouldNotBe null Was it not in a stack trace due to the assertSoftly? Any advice on making the stack traces easier to debug?

[sam]

Hmmm thatis crap I agree

[sam]

It might also be because it's a coroutine

[sam]

Try adding this somewhere

System.setProperty("kotlinx.coroutines.debug", "on")

[sam]

And if that helps, we should make sure kotest is setting it so you don't have to

[taer]

Of course now it's doing the right thing(the original test has morphed considerably

[taer]

weird. The other tests dont do this. There's something special about him. And no, the property setting didn't help

[taer]

Changing the assertSoftly to a with gets acceptable stacks again

[taer]

So other tests that use the same assertSoftly error nicely. There are no coroutines or suspend functions being tested here.

[taer]

some compiler helper? I will attach the 2 stack traces showing with vs asserrtSoftly.

[taer]

https://gist.github.com/robert-csdisco/4dddcf8313712d2ff69d899688ca9820

[sam]

So sometimes it works sometimes it doesn't?

[sam]

Do you have any threading goijg on

[taer]

None. It's a simple data generator.

[taer]

Like, given a tree of types, fill it out(think something like kotests ARB, etc)

[sam]

What about nested assertSoftyls ?

[taer]

I reproduced it cleanly.

[taer]

import io.kotest.assertions.assertSoftly
import io.kotest.core.spec.style.FunSpec
import io.kotest.matchers.shouldBe
import kotlin.random.Random

class ATest : FunSpec({

    val foo = Random(1)
    val x = foo.nextInt()
    test("asserts") {
        assertSoftly {
            x shouldBe  5
//            x shouldBe  6
    }}
})

[taer]

It seems like if you have just one assertion fail, you get the ugly stack trace. When I uncomment out the shouldBe 6, it has nice stacks

[taer]

digging in a bit more, but this line is what erases the goodies in stacktraces.kt

throwable.stackTrace = UserStackTraceConverter.getUserStacktrace(throwable.stackTrace)

[taer]

yeah. if only one tosses, then it's not wrapped in a MultiAssertion. If this line just always wrapped the list, I think it would work: https://github.com/kotest/kotest/blob/master/kotest-assertions/kotest-assertions-shared/src/commonMain/kotlin/io/kotest/assertions/ErrorCollector.kt

[taer]

It looks like MultiAssertionError's createMessage call would handle that just fine as well

[sam]

nice work thanks

[sam]

could you do me a favour and log a ticket with this info

[taer]

Sure sure

[taer]

I can PR fix that.. What direction would you prefer? Just throw the MultiAssertion failure w/ a single element? Or try to fix the filtering?

[sam]

I didn't fully understand the issue. Why does it fail if you only have 1 error. Because the clean doesn't work properly on a single errors but does on MultiAssertion ?

[taer]

yeah. The clean drops the stack traces till it finds a non-kotest. Actaully, that should instantly stop dropping in that case. I managed to checkout the code, I'll take a peek to see

[sam]

There's some tests for clean too, and that's one of the reasons all the tests are in com.sksamuel rather than io.kotest

[sam]

so we can see stacks

[sam]

It could be that the filtering is just broken in other ways

[sam]

Happy for a PR too yes

[taer]

ahh.. yeah. It's because "toList() here is the stackTrace array

[taer]

return toList().dropUntilFirstKotestClass().dropUntilFirstNonKotestClass().toTypedArray()

[taer]

it drops till it finds a kotest class, then drops till the non-kotest.

[taer]

in the single case, the top is non-kotest, so gets dropped

[taer]

wrapping the single in the MultiAssertion gives it something to find right at the top

[sam]

wouldn't this fail for all single assertions

[sam]

even those outside of softly

[sam]

and dropUntilFirstKotestClass will not drop anything if the first line is not kotest ?

[taer]

looks like when it's in hard mode, the error collectors throwCollectedErrors isn't called, and the error is just instantly rethrown

[taer]

fun ErrorCollector.collectOrThrow(error: Throwable) {
   when (getCollectionMode()) {
      ErrorCollectionMode.Soft -> pushError(error)
      ErrorCollectionMode.Hard -> throw error
   }
}

[sam]

sounds like we just need a bunch of tests around hard/soft multi/single stack trace cleaning

[sam]

and the issue will wash out

[taer]

yaeh.. I don't see the cleaning tests BTW

[taer]

is it in a different repo?

[taer]

never mind. intellij failure

[taer]

actually, the cleaning case seems like it just shouldn't be applied. The comment in dropUntilUserClass states

* Sometimes, it's possible for the Stacktrace to contain classes that are not from Kotest,
   * such as classes from sun.reflect or anything from Java. After clearing these classes, we'll be at Kotest
   * stacktrace, which will contain exceptions from the Runners and some other classes
   * After everything from Kotest we'll finally be at user classes, at which point the stacktrace is clean and is
   * returned.

In the simple case of 1 shouldBe 2, the top level class is the user's class. I don't see the cleaning call being made for anything other than the assertSoftly case TBH

[sam]

but isn't the 1 shouldBe 2 showing the user class because it's been cleaned ?

[taer]

ah.. was looking for the call only to UserStackTraceConverter.getUserStacktrace

[taer]

I think I see it..

[taer]

The shouldBe gets cleaned when it's thrown.

[taer]

Then the cleaned version is added to the list

[taer]

if it's an assertSoftly

[taer]

ie, the exception added to the list in the errorCollector has already been cleansed.

[taer]

The clean is working perfectly. The reason it works when you have 2+ assertions is the MultiAssertionError assertion error is created inside a io.kotest package, which will be stripped off

[taer]

maybe. I'm writing the tests now

[taer]

repushed. checking locally in our project as well

[taer]

It worked locally, and I pushed up. Fixed the compile error. It's failing now w/ what looks like a dependency issue perhaps?

java.lang.NoSuchMethodError: org.springframework.test.context.TestContext.computeAttribute(Ljava/lang/String;Ljava/util/function/Function;)Ljava/lang/Object;

[sam]

hmmm odd

[sam]

seems that way

[sam]

master is green

[sam]

but i guess if you only changed assert softly

[sam]

oh yeah master is broken because of some change

[sam]

ok I should have fixed master

[taer]

I'll re-start the I can push up a no-op to restart it

[sam]

ok