spock icon indicating copy to clipboard operation
spock copied to clipboard

Spock generates assertion reports with a changed state of object

Open piotrminkina opened this issue 6 months ago • 5 comments

Describe the bug

It seems that the assertion report from the expectation block is generated with a delay, rather than exactly when the verified expectation is not met. I am referring to the following example report of a mismatch between the expected value and the current value:

Condition not satisfied:

expectedValue == actualValue
|             |  |
123           |  124
              false

In my functional tests, I use the concept of drivers, which separate the implementation details of tests from the test case, allowing for clear tests even for non-technical people. These drivers are directly involved in verifying expectations by providing relevant details that help investigate why an expectation was not met in a given test case. This includes information about recently executed commands, environment variables, and anything else that could affect the fulfillment of expectations. A very useful and clear solution.

Consider the following test case:

class ExampleTest extends Specification {
    @TempDir File cwd
    def driver = new CommandDriver(cwd)

    def cleanup() {
        driver.execute('rm', '-rf', 'exampleDir')
    }

    def 'example test'() {
        when:
        driver.execute('mkdir', 'exampleDir')

        then:
        driver.execute('ls', '-al').text.contains('exampleDirzzz') // Deliberately unmet expectations
    }
}

As you can see, the expectation block is deliberately unfulfilled. I did this to show what the problem is. This is what the implementation of the sample driver looks like:

class CommandDriver {
    private ProcessBuilder builder
    private Process process

    final File currentWorkingDir

    CommandDriver(File currentWorkingDir) {
        this.currentWorkingDir = currentWorkingDir
    }

    Process execute(String... command) {
        builder = createProcessBuilder(command)
        process = builder.start()
        process.waitFor()

        return process
    }

    @Override
    String toString() {
        def description = 'Command Driver'

        if (builder) {
            description += [
                '',
                "- current working directory: ${builder.directory()}",
                '- command arguments:',
                builder.command().collect { "  - ${it}" },
            ].flatten().join(System.lineSeparator())
        }

        return description
    }

    protected ProcessBuilder createProcessBuilder(String... command) {
        def builder = new ProcessBuilder()
            .directory(currentWorkingDir)
            .command(command)
            .redirectErrorStream(true)

        return builder
    }
}

As you can see, in the toString() method, I display all the information that is useful for diagnosis. The report from the above test case looks like this:

Condition not satisfied:

driver.execute('ls', '-al').text.contains('exampleDirzzz')
|      |                    |    |
|      |                    |    false
|      |                    total 0
|      |                    drwx------.  3 piotrek piotrek   60 06-06 14:00 .
|      |                    drwxrwxrwt. 47 root    root    1240 06-06 14:00 ..
|      |                    drwxr-xr-x.  2 piotrek piotrek   40 06-06 14:00 exampleDir
|      Process[pid=533728, exitValue=0]
Command Driver
- current working directory: /tmp/spock_example_test_0_cwd16680776575184356238
- command arguments:
  - rm
  - -rf
  - exampleDir

The problem is in the command arguments: section, where ls -al (from the expectations block) should appear, but instead rm -rf exampleDir (from the cleanup method) appears.

This confirms my thesis from the beginning of this report. Spock generates a report with a delay. In my opinion, this is very problematic because it does not show the state that caused expectation not to be fulfilled. Between this block and the generation of the report, the state of the verified object, as in my case, may change.

To Reproduce

I am posting a project that illustrates this problem: spock-state.tar.gz

Expected behavior

The state presented in the report on unfulfilled expectations should be exactly the same as at the time of verification of this expectation.

Actual behavior

The changed state of objects is presented in the report on unmet expectations.

Java version

openjdk version "11.0.27" 2025-04-15 OpenJDK Runtime Environment Temurin-11.0.27+6 (build 11.0.27+6) OpenJDK 64-Bit Server VM Temurin-11.0.27+6 (build 11.0.27+6, mixed mode)

Buildtool version


Gradle 8.6

Build time: 2024-02-02 16:47:16 UTC Revision: d55c486870a0dc6f6278f53d21381396d0741c6e

Kotlin: 1.9.20 Groovy: 3.0.17 Ant: Apache Ant(TM) version 1.10.13 compiled on January 4 2023 JVM: 11.0.27 (Eclipse Adoptium 11.0.27+6) OS: Linux 6.14.9-200.fc41.x86_64 amd64

What operating system are you using

Linux

Dependencies

testRuntimeClasspath - Runtime classpath of source set 'test'.
+--- org.spockframework:spock-core:2.4-M6-groovy-3.0
|    +--- org.codehaus.groovy:groovy:3.0.24
|    +--- io.leangen.geantyref:geantyref:1.3.16
|    +--- org.spockframework:spock-bom:2.4-M6-groovy-3.0
|    |    \--- org.spockframework:spock-core:2.4-M6-groovy-3.0 (c)
|    +--- org.junit:junit-bom:5.12.2
|    |    +--- org.junit.platform:junit-platform-engine:1.12.2 (c)
|    |    +--- org.junit.platform:junit-platform-launcher:1.12.2 (c)
|    |    \--- org.junit.platform:junit-platform-commons:1.12.2 (c)
|    +--- org.junit.platform:junit-platform-engine -> 1.12.2
|    |    +--- org.junit:junit-bom:5.12.2 (*)
|    |    +--- org.opentest4j:opentest4j:1.3.0
|    |    \--- org.junit.platform:junit-platform-commons:1.12.2
|    |         \--- org.junit:junit-bom:5.12.2 (*)
|    \--- org.hamcrest:hamcrest:3.0
\--- org.junit.platform:junit-platform-launcher -> 1.12.2
     +--- org.junit:junit-bom:5.12.2 (*)
     \--- org.junit.platform:junit-platform-engine:1.12.2 (*)

Additional context

No response

piotrminkina avatar Jun 06 '25 12:06 piotrminkina

Below is another, much simpler example. All in all, I don't know what to think about it now.

class ExampleTest extends Specification {
    def 'another example'() {
        given:
        def state = new State()

        when:
        state.value = 123

        then:
        state.value == 124

        cleanup:
        state.value = 125
    }

    static class State {
        def value

        @Override
        String toString() {
            return value as String
        }
    }
}

This is a test report:

Condition not satisfied:

state.value == 124
|     |     |
125   123   false

piotrminkina avatar Jun 06 '25 13:06 piotrminkina

That's not so much a bug, more a performance optimization, besides that there is literally no way to get the behavior you expect.

For example consider this even simpler example:

import java.util.concurrent.atomic.AtomicInteger

class ExampleTest extends Specification {
    def 'another example'() {
        given:
        def i = new AtomicInteger(123)

        expect:
        i.andIncrement == 125
    }
}

which outputs

Condition not satisfied:
            
i.andIncrement == 125
| |            |
| 123          false
124

So the stimulus already modifies the state of the SUT. The assertion error is only created when the == fails, so even if the condition rendering would be created at that time, it would already be "wrong".

So to get a more correct result, you would need to create the rendering for each step, before the next step is executed, so the rendering for i needs to be done before the getAndIncrement is called for example. And this needs to be done, whether the rendering will be needed or not, because at that point you cannot know whether the rendering will be needed or not. Creating all these renderings up-front would be a performance nightmare as some of the renderings are also quite expensive to calculate.

And even then, it could produce wrong results or even worse wrong test results, if for example the toString call or whatever is used for the rendering (this is different for different types) could already modify the state, so the state would change before the assertion is checked so the test framework would influence the result and that should never happen.

The rendering is delayed until it is actually needed, that is until the assertion message is going to be printed to console or some report file the first time and then cached.

Actually, I had a similar situation in the past. I tested some CDI beans with Spock. And by the time the condition rendering happened, the CDI container was already shut down and thus the proxies that were used for the rendering were not valid anymore and couldn't be rendered properly.

I there decided to sacrifice a bit of performance by eagerly rendering the conditions after the feature method finished using this simple extension: https://github.com/Vampire/command-framework/blob/master/src/spock/java/net/kautler/test/spock/EagerExceptionRenderer.java

This would actually not fully help in your concrete examples, as the cleanup: block is part of the feature method and thus the rendering would still be too late. If the cleanup would have been in a cleanup method it would have helped though.

What might help in your case is to register an IRunListener to the specs in the extension and then do the eager rendering in the error method. I think that method should be called as soon as the error happened, so before a cleanup: block would change the state.

Of course the other things mentioned would still apply, so the example I wrote above would still print the same output as that is the state at the time the failure happens.

Vampire avatar Jun 06 '25 14:06 Vampire

Thank you very much for your detailed description of the problem. Thank you also for suggesting possible solutions for my case. I will definitely try to do something with the implementation of the IRunListener interface.

piotrminkina avatar Jun 09 '25 08:06 piotrminkina

The following code solves the problem. Thanks again @Vampire.

@CompileStatic
class EarlyRenderRunListener extends AbstractRunListener {
    @Override
    void error(ErrorInfo error) {
        if (error.exception instanceof ConditionNotSatisfiedError) {
            // force early render of the error message about not satisfied condition
            (error.exception as ConditionNotSatisfiedError).condition.rendering
        }
    }
}

Question: could this behavior be part of Spock's standard behavior?

piotrminkina avatar Jun 09 '25 14:06 piotrminkina

You can just "toString" all exceptions, no need to type-check and access internals.

Besides that, whether it will go into Spock @leonard84 has to decide, but I doubt it should. As I just explained, even with that behavior you don't get your expected behavior in all cases, and it is an intentional behavior to not render the cause prematurely, as it might not be use later and can be quite expensive to calculate.

Vampire avatar Jun 11 '25 01:06 Vampire

Thanks @Vampire, for the detailed answer and for providing a workaround. I agree with your reasoning about not changing anything in Spock.

leonard84 avatar Aug 24 '25 13:08 leonard84