Flaky test: Gradle's CachingTest

[Sanne]

Description

It seems this test has possibly been flaky for a long time (years?), but is most commonly reported by CI via an obscure message:

Failing: devtools/gradle/gradle-application-plugin 

📦 devtools/gradle/gradle-application-plugin

❌ Failed to execute goal org.codehaus.mojo:exec-maven-plugin:3.6.2:exec (gradle) on project io.quarkus.gradle.plugin: Command execution failed.

It's easier to reproduce locally with:

./gradlew clean :gradle-application-plugin:test --tests CachingTest.dotEnvChangeInvalidatesBuild

(occasionally) outputs:

STEP: remove FROM_DOT_ENV_FILE] 
Expecting map:
  {":assemble"=UP_TO_DATE, ":build"=UP_TO_DATE, ":check"=UP_TO_DATE, ":classes"=UP_TO_DATE, ":compileJava"=UP_TO_DATE, ":compileQuarkusTestGeneratedSourcesJava"=NO_SOURCE, ":compileTestJava"=NO_SOURCE, ":jar"=UP_TO_DATE, ":processResources"=NO_SOURCE, ":processTestResources"=NO_SOURCE, ":quarkusAppPartsBuild"=FROM_CACHE, ":quarkusBuild"=FROM_CACHE, ":quarkusBuildAppModel"=UP_TO_DATE, ":quarkusDependenciesBuild"=SUCCESS, ":quarkusGenerateAppModel"=UP_TO_DATE, ":quarkusGenerateCode"=FROM_CACHE, ":quarkusGenerateCodeTests"=FROM_CACHE, ":quarkusGenerateTestAppModel"=UP_TO_DATE, ":test"=NO_SOURCE, ":testClasses"=UP_TO_DATE}
to contain entries:
  [":quarkusDependenciesBuild"=SUCCESS,
    ":quarkusBuild"=SUCCESS,
    ":quarkusGenerateCode"=FROM_CACHE,
    ":build"=SUCCESS,
    ":quarkusAppPartsBuild"=FROM_CACHE,
    ":quarkusGenerateCodeTests"=FROM_CACHE]
but the following map entries had different values:
  [":quarkusBuild"=FROM_CACHE (expected: SUCCESS), ":build"=UP_TO_DATE (expected: SUCCESS)]
at CachingTest.assertBuildResult(CachingTest.java:243)
	at java.base@25.0.1/java.util.ArrayList.forEach(ArrayList.java:1604)
	at java.base@25.0.1/java.util.ArrayList.forEach(ArrayList.java:1604)

Implementation ideas

There are several things a little suspicious within this test, but I want to primarily address the flaky state at this point, which I suspect being caused by timing between the test changing the '.env' file on disk and a new build process being started right after - possibly further confounded by the fact that Gradle uses a virtual filesystem layer to cache state and a filesystem-watching deamon.

I'll give it a shot.

[quarkus-bot]

/cc @glefloch, @quarkusio/devtools

[gsmet]

I think @reaver585 has had a look at it?

[Sanne]

I think @reaver585 has had a look at it?

oh really? I think I have a fix, was about to send a PR... just running it a bit more times as I never know with flaky tests.

[reaver585]

I indeed have. There are two issues with this test:

First: I believe it's a well known problem at this point that generated-bytecode,jar is unstable, and that file is used as an input for quarkusBuild task. I'd say roughly 90% of the time, generated jar changes and that causes a gradle build cache miss.

Second: Why doesn't the test fail 90% of the time then, you may ask? Because, i think, the assertion logic is wrong.

    public static final Map<String, TaskOutcome> FROM_CACHE = Map.of(
            ":quarkusGenerateCode", TaskOutcome.FROM_CACHE,
            ":quarkusGenerateCodeTests", TaskOutcome.FROM_CACHE,
            ":quarkusAppPartsBuild", TaskOutcome.FROM_CACHE,
            ":quarkusDependenciesBuild", TaskOutcome.SUCCESS,
            ":quarkusBuild", TaskOutcome.SUCCESS,
            ":build", TaskOutcome.SUCCESS);

I think in an ideal scenraio, we should expect :quarkusBuild to have TaskOutcome.FROM_CACHE and thus, :build to have TaskOutcome.UP_TO_DATE. So, when the test fails 1 out of 10 times, it fails because the caching actually works 😄 So the output you observed, @Sanne, is actually what we should expect.

I was also suspicious of VFS behaviour at first, but I don't think it's an issue because same would happen to envChangeInvalidatesBuild() test (that doesn't deal with the file). It doesn't happen simply because that one scenario that is being checked in dotEnvChangeInvalidatesBuild() is not tested in envChangeInvalidatesBuild().

I believe true fix here is to make progress on the reproducible builds frontier, and we had a chat with @gsmet about that recently.

[Sanne]

Cool, thanks yes that looks to match what I was observing.

There's also something else strange in this test: the comments seems to suggest that the intent was to test for ~/.env (stored in the home), but it's not actually doing that: Paths.get(System.getProperty("user.dir")) resolves to the current working directory.
If I change this to "user.home" the test fails always - but it would seem the documentation suggests that ~/.env should be picked up.

The assumption at the beginning of the test is also not effective, as there is no check associated with it.

I have some changes ready which would make it more robust against VFS timings - it DOES NOT resolve the flaky test because I believe what you explained @reaver585 - I'll share it anyway though.

[reaver585]

Yeah, that situation with the location of .env file isn't intuitive. My understanding is that .env file only gets picked up when it's located in JVM's working directory, and user.dir leads exactly there. I tried putting dotenv into testProjectDir only to discover that it is ignored.

In the meantime, user.home leads to your $HOME, and dotenv is not there..

[Sanne]

I'm observing some failures which confuse me. At step "delete .env file" the expected output is state ALL_UP_TO_DATE - but this fails as it's actually FROM-CACHE. Initially I thought this was alarming, as clearly we wouldn't want to reuse the cached content after having made impactful changes - however the full logs show:

> Task :quarkusGenerateCodeTests FROM-CACHE
Build cache key for task ':quarkusGenerateCodeTests' is 50bcdfcebce488ad0c8ac01f09aa8502
Task ':quarkusGenerateCodeTests' is not up-to-date because:
  Value of input property 'cachingRelevantInput' has changed for task ':quarkusGenerateCodeTests'
Loaded cache entry for task ':quarkusGenerateCodeTests' with cache key 50bcdfcebce488ad0c8ac01f09aa8502
Resolve mutations for :compileJava (Thread[#1149,Execution worker Thread 9,5,main]) started.
:compileJava (Thread[#1149,Execution worker Thread 9,5,main]) started.

This suggests that while this is classed as "FROM-CACHE", it did seem to (correctly?) have recognized that the input has changed.

So the whole strategy for asserting based on these simple maps is wrong?

[Sanne]

Ha now I understand - it's tricky to test such things locally, as "FROM-CACHE" implies its recovering from a previous build even though it did in fact recognize the inputs changed. So yes the whole assertion strategy needs to take this into account.

[reaver585]

But it's still strange though. From your logs

Value of input property 'cachingRelevantInput' has changed for task ':quarkusGenerateCodeTests'

but it shouldn't have. In the previous step, the test removes FROM_DOT_ENV_FILE var from the dotenv file, which is a cache relevant property. However, by the time you delete dot env (in the next step), you didn't change cache relevant props compared to the last step.

It's also difficult to judge about failures that happen after the unstable remove FROM_DOT_ENV_FILE step.

[gsmet]

FWIW, I disabled it on Windows for now. Might disable it everywhere if it starts being in the way of the other builds.