Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Assertion calls on CapturedOutput with Kotlin are very slow #32033

Closed
aSemy opened this issue Aug 9, 2022 · 6 comments
Closed

Assertion calls on CapturedOutput with Kotlin are very slow #32033

aSemy opened this issue Aug 9, 2022 · 6 comments
Assignees
Labels
type: bug A general bug
Milestone

Comments

@aSemy
Copy link

aSemy commented Aug 9, 2022

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
    }
}
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Aug 9, 2022
@philwebb
Copy link
Member

philwebb commented Aug 9, 2022

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.

@philwebb
Copy link
Member

philwebb commented Aug 9, 2022

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

@philwebb philwebb added the status: waiting-for-feedback We need additional information before we can continue label Aug 9, 2022
@aSemy
Copy link
Author

aSemy commented Aug 9, 2022

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.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Aug 9, 2022
@scottfrederick
Copy link
Contributor

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.

@scottfrederick scottfrederick added the for: team-attention An issue we'd like other members of the team to review label Aug 15, 2022
@aSemy
Copy link
Author

aSemy commented Aug 15, 2022

Thank you @scottfrederick! I appreciate you investigating.

@philwebb philwebb added type: bug A general bug and removed for: team-attention An issue we'd like other members of the team to review status: waiting-for-triage An issue we've not yet triaged status: feedback-provided Feedback has been provided labels Aug 19, 2022
@philwebb philwebb added this to the 2.6.x milestone Aug 19, 2022
@philwebb
Copy link
Member

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

@philwebb philwebb changed the title Checking if CapturedOutput contains a string causes test to hang Assertion calls on CapturedOutput with Kotlin are very slow Oct 3, 2022
@philwebb philwebb self-assigned this Oct 3, 2022
@wilkinsona wilkinsona modified the milestones: 2.6.x, 2.6.13 Oct 4, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug A general bug
Projects
None yet
Development

No branches or pull requests

5 participants