Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve test/dev mode output #17784

Merged
merged 2 commits into from
Jun 9, 2021
Merged

Improve test/dev mode output #17784

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0e7f21d
Attempt to fix CT intermittent failures
stuartwdouglas Jun 9, 2021
12b9387
Improve continuous test/dev mode output
stuartwdouglas Jun 9, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
98 changes: 85 additions & 13 deletions core/deployment/src/main/java/io/quarkus/deployment/dev/RuntimeUpdatesProcessor.java
View file
Open in desktop
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
Open in desktop
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