From 0e7f21da6686c7b7b5ada9d0db3b49ade7336f52 Mon Sep 17 00:00:00 2001 From: Stuart Douglas Date: Wed, 9 Jun 2021 13:18:26 +1000 Subject: [PATCH 1/2] Attempt to fix CT intermittent failures Continuous testing tests can fail sometimes as an additional unexpected run is triggered. This is because a write is actually two seperate operations, a truncate followed by a write, so the update processor can see this as two seperate changes and trigger two seperate test runs (depending on the timing). This fixes it by re-checking the timestamps after compilation, and also attempting to re-compile if they don't match. --- .../dev/RuntimeUpdatesProcessor.java | 82 ++++++++++++++++--- 1 file changed, 71 insertions(+), 11 deletions(-) diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java index 92bb6239f0dfc..c57e77c0dbbfb 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java @@ -576,17 +576,63 @@ && sourceFileWasRecentModified(p, ignoreFirstScanChanges)) classScanResult.compilationHappened = true; log.info("Changed source files detected, recompiling " + changedSourceFiles.stream().map(File::getName).collect(Collectors.joining(", "))); - try { - final Set changedPaths = changedSourceFiles.stream() - .map(File::toPath) - .collect(Collectors.toSet()); - moduleChangedSourceFilePaths.addAll(changedPaths); - compiler.compile(sourcePath.toString(), changedSourceFiles.stream() - .collect(groupingBy(this::getFileExtension, Collectors.toSet()))); - compileProblem = null; - } catch (Exception e) { - compileProblem = e; - return new ClassScanResult(); + //so this is pretty yuck, but on a lot of systems a write is actually a truncate + write + //its possible we see the truncated file timestamp, then the write updates the timestamp + //which will then re-trigger continuous testing/live reload + //the empty fine does not normally cause issues as by the time we actually compile it the write + //has completed (but the old timestamp is used) + for (File i : changedSourceFiles) { + if (i.length() == 0) { + try { + //give time for the write to complete + //note that this is just 'best effort' + //the file time may have already been updated by the time we get here + Thread.sleep(200); + break; + } catch (InterruptedException e) { + //ignore + } + } + } + Map compileTimestamps = new HashMap<>(); + + //now we record the timestamps as they are before the compile phase + for (File i : changedSourceFiles) { + compileTimestamps.put(i, i.lastModified()); + } + for (;;) { + try { + final Set changedPaths = changedSourceFiles.stream() + .map(File::toPath) + .collect(Collectors.toSet()); + moduleChangedSourceFilePaths.addAll(changedPaths); + compiler.compile(sourcePath.toString(), changedSourceFiles.stream() + .collect(groupingBy(this::getFileExtension, Collectors.toSet()))); + compileProblem = null; + } catch (Exception e) { + compileProblem = e; + return new ClassScanResult(); + } + boolean timestampsChanged = false; + //check to make sure no changes have occurred while the compilation was + //taking place. If they have changed we update the timestamp in the compile + //time set, and re-run the compilation, as we have no idea if the compiler + //saw the old or new version + for (Map.Entry entry : compileTimestamps.entrySet()) { + if (entry.getKey().lastModified() != entry.getValue()) { + timestampsChanged = true; + entry.setValue(entry.getKey().lastModified()); + } + } + if (!timestampsChanged) { + break; + } + } + //now we re-update the underlying timestamps, to the values we just compiled + //if the file has changed in the meantime it will be picked up in the next + //scan + for (Map.Entry entry : compileTimestamps.entrySet()) { + sourceFileTimestamps.put(entry.getKey().toPath(), entry.getValue()); } } @@ -780,6 +826,20 @@ Set checkForFileChange(Function existing) { ret.add(path); + //a write can be a 'truncate' + 'write' + //if the file is empty we may be seeing the middle of a write + if (Files.size(file) == 0) { + try { + Thread.sleep(200); + } catch (InterruptedException e) { + //ignore + } + } + //re-read, as we may have read the original TS if the middle of + //a truncate+write, even if the write had completed by the time + //we read the size + value = Files.getLastModifiedTime(file).toMillis(); + log.infof("File change detected: %s", file); if (doCopy && !Files.isDirectory(file)) { Path target = outputDir.resolve(path); From 12b938724372d5b621d6516803c2d9ecb7c1f243 Mon Sep 17 00:00:00 2001 From: Stuart Douglas Date: Wed, 9 Jun 2021 14:58:21 +1000 Subject: [PATCH 2/2] Improve continuous test/dev mode output - Fix output if no tests run - Display time test were run - Remove compiling log message, replace with message for test/dev mode restart with changed classes. - Don't count skipped tests towards the number run --- .../dev/RuntimeUpdatesProcessor.java | 16 ++++++- .../dev/testing/TestConsoleHandler.java | 47 +++++++++++++++---- 2 files changed, 52 insertions(+), 11 deletions(-) diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java index c57e77c0dbbfb..62edd7ce0f8da 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java @@ -375,6 +375,17 @@ public boolean doScan(boolean userInitiated, boolean force) throws IOException { boolean configFileRestartNeeded = filesChanged.stream().map(main.watchedFilePaths::get) .anyMatch(Boolean.TRUE::equals); boolean instrumentationChange = false; + + List changedFilesForRestart = new ArrayList<>(); + if (configFileRestartNeeded) { + changedFilesForRestart + .addAll(filesChanged.stream().filter(fn -> Boolean.TRUE.equals(main.watchedFilePaths.get(fn))) + .map(Paths::get).collect(Collectors.toList())); + } + changedFilesForRestart.addAll(changedClassResults.getChangedClasses()); + changedFilesForRestart.addAll(changedClassResults.getAddedClasses()); + changedFilesForRestart.addAll(changedClassResults.getDeletedClasses()); + if (ClassChangeAgent.getInstrumentation() != null && lastStartIndex != null && !configFileRestartNeeded && devModeType != DevModeType.REMOTE_LOCAL_SIDE) { //attempt to do an instrumentation based reload @@ -428,6 +439,9 @@ public boolean doScan(boolean userInitiated, boolean force) throws IOException { boolean restartNeeded = !instrumentationChange && (changedClassResults.isChanged() || (IsolatedDevModeMain.deploymentProblem != null && userInitiated) || configFileRestartNeeded); if (restartNeeded) { + String changeString = changedFilesForRestart.stream().map(Path::getFileName).map(Object::toString) + .collect(Collectors.joining(", ")) + "."; + log.infof("Restarting quarkus due to changes in " + changeString); restartCallback.accept(filesChanged, changedClassResults); long timeNanoSeconds = System.nanoTime() - startNanoseconds; log.infof("Live reload total time: %ss ", Timing.convertToBigDecimalSeconds(timeNanoSeconds)); @@ -574,8 +588,6 @@ && sourceFileWasRecentModified(p, ignoreFirstScanChanges)) } if (!changedSourceFiles.isEmpty()) { classScanResult.compilationHappened = true; - log.info("Changed source files detected, recompiling " - + changedSourceFiles.stream().map(File::getName).collect(Collectors.joining(", "))); //so this is pretty yuck, but on a lot of systems a write is actually a truncate + write //its possible we see the truncated file timestamp, then the write updates the timestamp //which will then re-trigger continuous testing/live reload diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/TestConsoleHandler.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/TestConsoleHandler.java index 275c219707e55..04d1809d19504 100644 --- a/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/TestConsoleHandler.java +++ b/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/TestConsoleHandler.java @@ -7,10 +7,14 @@ import static io.quarkus.deployment.dev.testing.TestConsoleHandler.MessageFormat.helpOption; import static io.quarkus.deployment.dev.testing.TestConsoleHandler.MessageFormat.statusFooter; import static io.quarkus.deployment.dev.testing.TestConsoleHandler.MessageFormat.statusHeader; -import static io.quarkus.deployment.dev.testing.TestConsoleHandler.MessageFormat.toggleStatus; import java.io.IOException; +import java.nio.file.Path; +import java.text.SimpleDateFormat; +import java.util.Date; +import java.util.LinkedHashSet; import java.util.Map; +import java.util.Set; import java.util.concurrent.atomic.AtomicLong; import java.util.function.Consumer; @@ -19,6 +23,7 @@ import org.junit.platform.launcher.TestIdentifier; import io.quarkus.bootstrap.classloading.QuarkusClassLoader; +import io.quarkus.deployment.dev.ClassScanResult; import io.quarkus.deployment.dev.RuntimeUpdatesProcessor; import io.quarkus.dev.console.InputHandler; import io.quarkus.dev.console.QuarkusConsole; @@ -34,6 +39,7 @@ public class TestConsoleHandler implements TestListener { boolean firstRun = true; boolean disabled = true; + boolean currentlyFailing = false; volatile InputHandler.ConsoleStatus promptHandler; volatile TestController testController; private String lastStatus; @@ -165,17 +171,43 @@ public void testComplete(TestResult result) { @Override public void runComplete(TestRunResults results) { firstRun = false; - if (results.getCurrentTotalCount() == 0) { + SimpleDateFormat df = new SimpleDateFormat("kk:mm:ss"); + + String end = " Tests completed at " + df.format(new Date()); + if (results.getTrigger() != null) { + ClassScanResult trigger = results.getTrigger(); + Set paths = new LinkedHashSet<>(); + paths.addAll(trigger.getChangedClasses()); + paths.addAll(trigger.getAddedClasses()); + paths.addAll(trigger.getDeletedClasses()); + if (paths.size() == 1) { + end = end + " due to changes to " + paths.iterator().next().getFileName() + "."; + } else if (paths.size() > 1) { + end = end + " due to changes to " + paths.iterator().next().getFileName() + " and " + (paths.size() - 1) + + " other files."; + } else { + //should never happen + end = end + "."; + } + } else { + end = end + "."; + } + if (results.getTotalCount() == 0) { lastStatus = YELLOW + "No tests found" + RESET; } else if (results.getFailedCount() == 0 && results.getPassedCount() == 0) { lastStatus = String.format(YELLOW + "All %d tests were skipped" + RESET, results.getSkippedCount()); } else if (results.getCurrentFailing().isEmpty()) { + if (currentlyFailing) { + log.info(GREEN + "All tests are now passing" + RESET); + } + currentlyFailing = false; lastStatus = String.format( - GREEN + "All %d tests are passing (%d skipped), %d tests were run in %dms." + RESET, + GREEN + "All %d tests are passing (%d skipped), %d tests were run in %dms." + end + RESET, results.getPassedCount(), results.getSkippedCount(), - results.getCurrentTotalCount(), results.getTotalTime()); + results.getCurrentTotalCount() - results.getSkippedCount(), results.getTotalTime()); } else { + currentlyFailing = true; //TODO: this should not use the logger, it should print a nicer status log.error(statusHeader("TEST REPORT #" + results.getId())); for (Map.Entry classEntry : results.getCurrentFailing().entrySet()) { @@ -189,7 +221,7 @@ public void runComplete(TestRunResults results) { statusFooter(RED + results.getCurrentFailedCount() + " TESTS FAILED")); lastStatus = String.format( RED + "%d tests failed" + RESET + " (" + GREEN + "%d passing" + RESET + ", " + YELLOW + "%d skipped" - + RESET + "), %d tests were run in %dms." + RESET, + + RESET + "), %d tests were run in %dms." + end + RESET, results.getCurrentFailedCount(), results.getPassedCount(), results.getSkippedCount(), results.getCurrentTotalCount(), results.getTotalTime()); } @@ -200,10 +232,7 @@ public void runComplete(TestRunResults results) { @Override public void noTests(TestRunResults results) { - firstRun = false; - lastStatus = "No tests to run"; - promptHandler.setStatus(lastStatus); - promptHandler.setPrompt(RUNNING_PROMPT); + runComplete(results); } @Override