SpringBoot Assertion calls on CapturedOutput with Kotlin are very slow

I have a test that checks to see if a string is in the captured output. I expect this to work because CapturedOutput implements CharSequence. However, the test hangs indefinitely.

// this test hangs indefinitely
@Test
fun `check if output contains string`(output: CapturedOutput) {
    assertAll(
        { assertTrue("Started" in output) },
    )
}

I would expect that this works the same as if I had called output.all.

// this test works as expected
@Test
fun `check if output contains string`(output: CapturedOutput) {
    assertAll(
        { assertTrue("Started" in output.all) },
    )
}

• Spring Boot 2.7.2
• Kotlin 1.7.10
• Gradle 7.5.1

ApplicationTest.kt

import org.junit.jupiter.api.Assertions.assertAll
import org.junit.jupiter.api.Assertions.assertNotNull
import org.junit.jupiter.api.Assertions.assertTrue
import org.junit.jupiter.api.Test
import org.junit.jupiter.api.extension.ExtendWith
import org.junit.jupiter.api.parallel.Isolated
import org.springframework.boot.test.context.SpringBootTest
import org.springframework.boot.test.context.SpringBootTest.WebEnvironment.RANDOM_PORT
import org.springframework.boot.test.system.CapturedOutput
import org.springframework.boot.test.system.OutputCaptureExtension
import org.springframework.context.ApplicationContext
import org.springframework.test.annotation.DirtiesContext

@SpringBootTest(
    classes = [Application::class],
    webEnvironment = RANDOM_PORT,
)
@ExtendWith(OutputCaptureExtension::class)
internal class ApplicationTest {

    @Test
    fun `expect Spring Context loads`(context: ApplicationContext?) {
        assertNotNull(context)
    }

    @Test
    fun `check if output contains string`(output: CapturedOutput) {
        assertAll(
            { assertTrue("Started" in output) },
        )
    }
}

Application.kt

import org.springframework.boot.autoconfigure.AutoConfigurationExcludeFilter
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.context.TypeExcludeFilter
import org.springframework.boot.context.properties.ConfigurationPropertiesScan
import org.springframework.boot.context.properties.EnableConfigurationProperties
import org.springframework.boot.runApplication
import org.springframework.context.annotation.ComponentScan
import org.springframework.context.annotation.ComponentScan.Filter
import org.springframework.context.annotation.FilterType.CUSTOM
import org.springframework.context.annotation.FullyQualifiedAnnotationBeanNameGenerator

@SpringBootApplication
@ComponentScan(
    excludeFilters = [
        Filter(type = CUSTOM, classes = [TypeExcludeFilter::class]),
        Filter(type = CUSTOM, classes = [AutoConfigurationExcludeFilter::class])
    ],
    nameGenerator = FullyQualifiedAnnotationBeanNameGenerator::class
)
@EnableConfigurationProperties
class Application

fun main() {
    try {
        runApplication<Application>()
    } catch (e: Exception) {
        e.printStackTrace()
        throw e
    }
}

Comment From: philwebb

Could you please attach a sample project that we can download and run. The snippets are helpful, but a full project with a build file will be better to ensure we're on the same versions and haven't made a mistake copying the code.

Comment From: philwebb

Also, if you can replicate this in Java that will be even better as there's one less moving part.

Comment From: aSemy

example-capturedoutput-32033.zip

Example project attached.

It's related to the root log level. When I set it to INFO, it works. When it's set as DEBUG, the test hangs.

Comment From: scottfrederick

I can't reproduce the hanging test with the provided sample, but the this test hangs test does take as long as 30 seconds to run. It is likely to take exponentially longer with more captured output (which is why you see a difference between log levels INFO and DEBUG).

The problem is specific to Kotlin. A statement like assertTrue("Started ApplicationTest" in output) treats output as a CharSequence and invokes Kotlin's CharSequence.contains. This calls the length() and charAt() methods of Spring Boot's CapturedOutput class many times. These methods are not very efficient, as they call toString() and assemble a String from the captured output with each call.

When calling assertTrue("Started ApplicationTest" in output.all), the result of output.all is a String so the CharSequence.contains method is not called and the test executes very quickly. This is essentially the same as calling assertTrue("Started ApplicationTest" in output.toString()). assertThat(output).contains("Started ApplicationTest") is also very fast.

Marking this for team attention so we can decide what, if anything, we want to do about this.

Comment From: aSemy

Thank you @scottfrederick! I appreciate you investigating.

Comment From: philwebb

I think we should add some caching to org.springframework.boot.test.system.OutputCapture so that repeated calls are faster.