Undertow ServletChangeTestCase fails most of the time

It's semi-random, and I can't reproduce it in the IDE where the test always passes, but on the CLI it fails every time now for me, even though I've bumped the sleeps to 3s.

Running them, I do observe some behaviour differences between the CLI:

[INFO] Running io.quarkus.undertow.test.devmode.ServletChangeTestCase
2019-08-21 16:31:38,049 INFO  [io.qua.dep.QuarkusAugmentor] (main) Beginning quarkus augmentation
2019-08-21 16:31:38,235 INFO  [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 186ms
2019-08-21 16:31:38,289 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.054s. Listening on: http://0.0.0.0:8080
2019-08-21 16:31:38,290 INFO  [io.quarkus] (main) Installed features: [cdi, vertx, vertx-web]
Modifying file DevServlet.java
Modifying file DevServlet.java done
Modifying file DevServlet.java done sleeping
2019-08-21 16:31:39,087 INFO  [io.quarkus] (main) Quarkus stopped in 0.049s
2019-08-21 16:31:39,131 INFO  [io.qua.dep.QuarkusAugmentor] (main) Beginning quarkus augmentation
2019-08-21 16:31:39,277 INFO  [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 146ms
2019-08-21 16:31:39,307 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.029s. Listening on: http://0.0.0.0:8080
2019-08-21 16:31:39,308 INFO  [io.quarkus] (main) Installed features: [cdi, vertx, vertx-web]
2019-08-21 16:31:39,391 INFO  [io.quarkus] (main) Quarkus stopped in 0.001s
2019-08-21 16:31:39,418 INFO  [io.qua.dep.QuarkusAugmentor] (main) Beginning quarkus augmentation
2019-08-21 16:31:39,553 INFO  [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 135ms
2019-08-21 16:31:39,582 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.028s. Listening on: http://0.0.0.0:8080
2019-08-21 16:31:39,583 INFO  [io.quarkus] (main) Installed features: [cdi, vertx, vertx-web]
2019-08-21 16:31:39,616 INFO  [io.quarkus] (main) Quarkus stopped in 0.000s
2019-08-21 16:31:39,642 INFO  [io.qua.dep.QuarkusAugmentor] (main) Beginning quarkus augmentation
2019-08-21 16:31:39,759 INFO  [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 117ms
2019-08-21 16:31:39,790 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.030s. Listening on: http://0.0.0.0:8080
2019-08-21 16:31:39,790 INFO  [io.quarkus] (main) Installed features: [cdi, vertx, vertx-web]
2019-08-21 16:31:42,017 INFO  [io.qua.dev] (vert.x-worker-thread-7) Changed source files detected, recompiling [/home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test1693195026420937884/src/main/java/io/quarkus/undertow/test/devmode/NewServlet.java]
2019-08-21 16:31:42,529 INFO  [io.quarkus] (vert.x-worker-thread-7) Quarkus stopped in 0.002s
2019-08-21 16:31:42,530 INFO  [io.qua.dep.QuarkusAugmentor] (vert.x-worker-thread-7) Beginning quarkus augmentation
2019-08-21 16:31:42,644 INFO  [io.qua.dep.QuarkusAugmentor] (vert.x-worker-thread-7) Quarkus augmentation completed in 114ms
2019-08-21 16:31:42,675 INFO  [io.quarkus] (vert.x-worker-thread-7) Quarkus 999-SNAPSHOT started in 0.146s. Listening on: http://0.0.0.0:8080
2019-08-21 16:31:42,675 INFO  [io.quarkus] (vert.x-worker-thread-7) Installed features: [cdi, vertx, vertx-web]
2019-08-21 16:31:42,675 INFO  [io.qua.dev] (vert.x-worker-thread-7) Hot replace total time: 0.659s 
2019-08-21 16:31:42,687 INFO  [io.quarkus] (main) Quarkus stopped in 0.002s
[ERROR] Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 4.688 s <<< FAILURE! - in io.quarkus.undertow.test.devmode.ServletChangeTestCase
[ERROR] testServletChange  Time elapsed: 1.101 s  <<< FAILURE!
java.lang.AssertionError: 
1 expectation failed.
Response body doesn't match expectation.
Expected: is "Hello Quarkus"
  Actual: Hello World

    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:83)
    at org.codehaus.groovy.reflection.CachedConstructor.doConstructorInvoke(CachedConstructor.java:77)
    at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrap.callConstructor(ConstructorSite.java:84)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:59)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:238)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:250)
    at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure.validate(ResponseSpecificationImpl.groovy:494)
    at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure$validate$1.call(Unknown Source)
    at io.restassured.internal.ResponseSpecificationImpl.validateResponseIfRequired(ResponseSpecificationImpl.groovy:656)
    at sun.reflect.GeneratedMethodAccessor50.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:210)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)
    at io.restassured.internal.ResponseSpecificationImpl.content(ResponseSpecificationImpl.groovy:97)
    at io.restassured.specification.ResponseSpecification$content$1.callCurrent(Unknown Source)
    at io.restassured.internal.ResponseSpecificationImpl.body(ResponseSpecificationImpl.groovy:256)
    at io.restassured.internal.ValidatableResponseOptionsImpl.body(ValidatableResponseOptionsImpl.java:268)
    at io.quarkus.undertow.test.devmode.ServletChangeTestCase.testServletChange(ServletChangeTestCase.java:46)

And the IDE:

Aug 21, 2019 4:34:52 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Beginning quarkus augmentation
Aug 21, 2019 4:34:52 PM org.jboss.threads.Version <clinit>
INFO: JBoss Threads version 3.0.0.Beta5
Aug 21, 2019 4:34:53 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Quarkus augmentation completed in 674ms
Aug 21, 2019 4:34:53 PM io.quarkus.runtime.Timing printStartupTime
INFO: Quarkus 999-SNAPSHOT started in 0.357s. Listening on: http://0.0.0.0:8080
Aug 21, 2019 4:34:53 PM io.quarkus.runtime.Timing printStartupTime
INFO: Installed features: [cdi, vertx, vertx-web]
Modifying file DevServlet.java
Modifying file DevServlet.java done
Modifying file DevServlet.java done sleeping
Aug 21, 2019 4:34:57 PM io.quarkus.dev.RuntimeUpdatesProcessor checkForChangedClasses
INFO: Changed source files detected, recompiling [/tmp/quarkus-dev-mode-test2265122520589184262/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java]
Aug 21, 2019 4:34:57 PM io.quarkus.runtime.Timing printStopTime
INFO: Quarkus stopped in 0.044s
Aug 21, 2019 4:34:57 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Beginning quarkus augmentation
Aug 21, 2019 4:34:57 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Quarkus augmentation completed in 183ms
Aug 21, 2019 4:34:57 PM io.quarkus.runtime.Timing printStartupTime
INFO: Quarkus 999-SNAPSHOT started in 0.208s. Listening on: http://0.0.0.0:8080
Aug 21, 2019 4:34:57 PM io.quarkus.runtime.Timing printStartupTime
INFO: Installed features: [cdi, vertx, vertx-web]
Aug 21, 2019 4:34:57 PM io.quarkus.dev.RuntimeUpdatesProcessor doScan
INFO: Hot replace total time: 0.772s 
Modifying file DevServlet.java
Modifying file DevServlet.java done
Modifying file DevServlet.java done sleeping
Aug 21, 2019 4:35:00 PM io.quarkus.dev.RuntimeUpdatesProcessor checkForChangedClasses
INFO: Changed source files detected, recompiling [/tmp/quarkus-dev-mode-test2265122520589184262/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java]
Aug 21, 2019 4:35:00 PM io.quarkus.runtime.Timing printStopTime
INFO: Quarkus stopped in 0.001s
Aug 21, 2019 4:35:00 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Beginning quarkus augmentation
Aug 21, 2019 4:35:00 PM io.quarkus.deployment.QuarkusAugmentor run
INFO: Quarkus augmentation completed in 204ms
Aug 21, 2019 4:35:00 PM io.quarkus.runtime.Timing printStartupTime
INFO: Quarkus 999-SNAPSHOT started in 0.239s. Listening on: http://0.0.0.0:8080
Aug 21, 2019 4:35:00 PM io.quarkus.runtime.Timing printStartupTime
INFO: Installed features: [cdi, vertx, vertx-web]
Aug 21, 2019 4:35:00 PM io.quarkus.dev.RuntimeUpdatesProcessor doScan
INFO: Hot replace total time: 0.321s 
Aug 21, 2019 4:35:00 PM io.quarkus.runtime.Timing printStopTime
INFO: Quarkus stopped in 0.002s

For instance, in the IDE, there is a sleep of 3s that is not observed in the CLI (for some reason), and the in the IDE the change is picked up right away on the next request, while on the CLI there appears to be 3 restarts before the change is picked up. No idea why those restarts…

That's not the issue. The issue is that we're writing the test file at time 1000 (ms), then the dev mode server catches the current time millis which say 2025 ms, and we do the modification at 2000 ms and the modification isn't picked up.

Proof:

[INFO] Running io.quarkus.undertow.test.devmode.ServletChangeTestCase
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java ispresent: true
wasRecentlyModified /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java sourceMod: 1566401423000 lastChange: 1566401425039
2019-08-21 17:30:25,047 INFO  [io.qua.dep.QuarkusAugmentor] (main) Beginning quarkus augmentation
2019-08-21 17:30:25,201 INFO  [io.qua.dep.QuarkusAugmentor] (main) Quarkus augmentation completed in 154ms
2019-08-21 17:30:25,265 INFO  [io.quarkus] (main) Quarkus 999-SNAPSHOT started in 0.063s. Listening on: http://0.0.0.0:8080
2019-08-21 17:30:25,266 INFO  [io.quarkus] (main) Installed features: [cdi, vertx, vertx-web]
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java ispresent: true
wasRecentlyModified /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java sourceMod: 1566401423000 lastChange: 1566401425039
Checked for file changes: [] classes changed: false
Modifying file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java
Modifying file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java done
Modifying file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java done sleeping
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode ispresent: false
Watching source file /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java ispresent: true
wasRecentlyModified /home/stephane/src/java-eclipse/quarkus/extensions/undertow/deployment/target/quarkus-dev-mode-test8002444265299259795/src/main/java/io/quarkus/undertow/test/devmode/DevServlet.java sourceMod: 1566401425000 lastChange: 1566401425039
Checked for file changes: [] classes changed: false

So there are two mysteries:

Why does the lastModified file round on seconds
Why does the initial currentTimeMillis() used by lastChange start greater than the file modification which occurs later?

quarkusio / quarkus

Undertow ServletChangeTestCase fails most of the time #3621