Skip to content

Commit

Permalink
Merge pull request #17784 from stuartwdouglas/dev-mode-output
Browse files Browse the repository at this point in the history 
Improve test/dev mode output
  • Loading branch information
@stuartwdouglas
stuartwdouglas authored Jun 9, 2021
2 parents 2dc3fa6 + 12b9387 commit 26a7808
Show file tree
Hide file tree
Showing 2 changed files with 123 additions and 22 deletions.
98 changes: 85 additions & 13 deletions core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<Path> 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
Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -574,19 +588,63 @@ && sourceFileWasRecentModified(p, ignoreFirstScanChanges))
}
if (!changedSourceFiles.isEmpty()) {
classScanResult.compilationHappened = true;
log.info("Changed source files detected, recompiling "
+ changedSourceFiles.stream().map(File::getName).collect(Collectors.joining(", ")));
try {
final Set<Path> 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<File, Long> 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<Path> 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<File, Long> 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<File, Long> entry : compileTimestamps.entrySet()) {
sourceFileTimestamps.put(entry.getKey().toPath(), entry.getValue());
}
}

Expand Down Expand Up @@ -780,6 +838,20 @@ Set<String> checkForFileChange(Function<DevModeContext.ModuleInfo, DevModeContex
//as there is both normal and test resources, but only one set of watched timestampts
if (existing != null && value > 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);
Expand Down
47 changes: 38 additions & 9 deletions core/deployment/src/main/java/io/quarkus/deployment/dev/testing/TestConsoleHandler.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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<Path> 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<String, TestClassResult> classEntry : results.getCurrentFailing().entrySet()) {
Expand All @@ -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());
}
Expand All @@ -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
Expand Down

0 comments on commit 26a7808

Please sign in to comment.