Make Dev Services logging nicer

This changes the mass of Dev Services logging to a single status line per starting container. This allows the user to see that progress is happening, without flooding the console. If the operation fails all captured output is dumped. Fixes #16203
quarkusio · Sep 7, 2021 · 34ef1f9 · 34ef1f9
1 parent 5c63f10
commit 34ef1f9
Show file tree

Hide file tree

Showing 14 changed files with 357 additions and 146 deletions.
diff --git a/core/deployment/src/main/java/io/quarkus/deployment/console/AeshConsole.java b/core/deployment/src/main/java/io/quarkus/deployment/console/AeshConsole.java
@@ -55,6 +55,7 @@ protected Boolean initialValue() {
     static final TreeMap<Integer, StatusLineImpl> statusMap = new TreeMap<>();
     private final ReadWriteLock positionLock = new ReentrantReadWriteLock();
     private volatile boolean closed;
+    private final StatusLine prompt;
 
     public AeshConsole(Connection connection) {
         INSTANCE = this;
@@ -67,6 +68,7 @@ public void run() {
                 connection.close();
             }
         }, "Console Shutdown Hook"));
+        prompt = registerStatusLine(0);
     }
 
     private void updatePromptOnChange(StringBuilder buffer, int newLines) {
@@ -109,7 +111,7 @@ public StatusLine registerStatusLine(int priority) {
 
     @Override
     public void setPromptMessage(String promptMessage) {
-        setMessage(0, promptMessage);
+        prompt.setMessage(promptMessage);
     }
 
     private AeshConsole setMessage(int position, String message) {
@@ -386,6 +388,11 @@ public void write(boolean errorStream, byte[] buf, int off, int len) {
         write(errorStream, new String(buf, off, len, connection.outputEncoding()));
     }
 
+    @Override
+    public boolean isAnsiSupported() {
+        return true;
+    }
+
     @Override
     public void doReadLine() {
         setPromptMessage("");
@@ -395,10 +402,13 @@ public void doReadLine() {
     }
 
     void rebalance() {
-        int count = 1;
-        for (var val : statusMap.values()) {
-            val.position = count;
-            setMessage(count++, val.message);
+        synchronized (this) {
+            int count = 1;
+            messages = new String[statusMap.size()];
+            for (var val : statusMap.values()) {
+                val.position = count;
+                setMessage(count++, val.message);
+            }
         }
     }
 
@@ -407,17 +417,20 @@ class StatusLineImpl implements StatusLine {
         final int priority;
         int position;
         String message;
+        boolean closed;
 
         StatusLineImpl(int priority) {
             this.priority = priority;
         }
 
         @Override
         public void setMessage(String message) {
-            this.message = message;
             try {
                 positionLock.readLock().lock();
-                AeshConsole.this.setMessage(position, message);
+                this.message = message;
+                if (!closed) {
+                    AeshConsole.this.setMessage(position, message);
+                }
             } finally {
                 positionLock.readLock().unlock();
             }
@@ -426,6 +439,7 @@ public void setMessage(String message) {
         @Override
         public void close() {
             positionLock.writeLock().lock();
+            closed = true;
             try {
                 AeshConsole.this.setMessage(position, null);
                 statusMap.remove(priority);

diff --git a/core/deployment/src/main/java/io/quarkus/deployment/console/ConsoleInstalledBuildItem.java b/core/deployment/src/main/java/io/quarkus/deployment/console/ConsoleInstalledBuildItem.java
@@ -0,0 +1,13 @@
+package io.quarkus.deployment.console;
+
+import io.quarkus.builder.item.SimpleBuildItem;
+
+/**
+ * Build item that signifies that the interactive console is ready.
+ *
+ * This will not always be present, as the console may not be installed
+ */
+public final class ConsoleInstalledBuildItem extends SimpleBuildItem {
+
+    public static final ConsoleInstalledBuildItem INSTANCE = new ConsoleInstalledBuildItem();
+}
diff --git a/core/deployment/src/main/java/io/quarkus/deployment/console/ConsoleProcessor.java b/core/deployment/src/main/java/io/quarkus/deployment/console/ConsoleProcessor.java
@@ -27,11 +27,12 @@ public class ConsoleProcessor {
      */
     @BuildStep(onlyIf = IsDevelopment.class)
     @Produce(TestSetupBuildItem.class)
-    void setupConsole(TestConfig config, BuildProducer<TestListenerBuildItem> testListenerBuildItemBuildProducer,
+    ConsoleInstalledBuildItem setupConsole(TestConfig config,
+            BuildProducer<TestListenerBuildItem> testListenerBuildItemBuildProducer,
             LaunchModeBuildItem launchModeBuildItem, ConsoleConfig consoleConfig) {
 
         if (consoleInstalled) {
-            return;
+            return ConsoleInstalledBuildItem.INSTANCE;
         }
         consoleInstalled = true;
         if (config.console.orElse(consoleConfig.enabled)) {
@@ -49,11 +50,12 @@ void setupConsole(TestConfig config, BuildProducer<TestListenerBuildItem> testLi
             //note that this bit needs to be refactored so it is no longer tied to continuous testing
             if (!TestSupport.instance().isPresent() || config.continuousTesting == TestConfig.Mode.DISABLED
                     || config.flatClassPath) {
-                return;
+                return ConsoleInstalledBuildItem.INSTANCE;
             }
             TestConsoleHandler consoleHandler = new TestConsoleHandler(launchModeBuildItem.getDevModeType().get());
             consoleHandler.install();
             testListenerBuildItemBuildProducer.produce(new TestListenerBuildItem(consoleHandler));
         }
+        return ConsoleInstalledBuildItem.INSTANCE;
     }
 }
diff --git a/core/deployment/src/main/java/io/quarkus/deployment/console/StartupLogCompressor.java b/core/deployment/src/main/java/io/quarkus/deployment/console/StartupLogCompressor.java
@@ -0,0 +1,65 @@
+package io.quarkus.deployment.console;
+
+import java.io.Closeable;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Optional;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.function.BiPredicate;
+
+import io.quarkus.deployment.dev.testing.MessageFormat;
+import io.quarkus.deployment.logging.LoggingSetupBuildItem;
+import io.quarkus.dev.console.QuarkusConsole;
+import io.quarkus.dev.console.StatusLine;
+
+/**
+ * special filter that can be used to compress log messages to a status line
+ * <p>
+ * This is useful for Dev Services to show progress without cluttering up the logs
+ */
+public class StartupLogCompressor implements Closeable, BiPredicate<String, Boolean> {
+
+    final Thread thread;
+    final String name;
+    volatile StatusLine sl;
+    final List<String> toDump = new ArrayList<>();
+    final AtomicInteger COUNTER = new AtomicInteger();
+
+    public StartupLogCompressor(String name, Optional<ConsoleInstalledBuildItem> consoleInstalledBuildItem,
+            LoggingSetupBuildItem loggingSetupBuildItem) {
+        ConsoleHelper.installRedirects();
+        this.name = name;
+        this.thread = Thread.currentThread();
+        QuarkusConsole.addOutputFilter(this);
+        sl = QuarkusConsole.INSTANCE.registerStatusLine(1000 + COUNTER.incrementAndGet());
+        sl.setMessage(MessageFormat.BLUE + name + MessageFormat.RESET);
+    }
+
+    @Override
+    public void close() {
+        QuarkusConsole.removeOutputFilter(this);
+        sl.close();
+    }
+
+    public void closeAndDumpCaptured() {
+        QuarkusConsole.removeOutputFilter(this);
+        sl.close();
+        for (var i : toDump) {
+            QuarkusConsole.INSTANCE.write(true, i);
+        }
+    }
+
+    @Override
+    public boolean test(String s, Boolean errorStream) {
+        if (Thread.currentThread() == thread) {
+            if (!QuarkusConsole.INSTANCE.isAnsiSupported()) {
+                return true;
+            }
+            toDump.add(s);
+            sl.setMessage(MessageFormat.BLUE + name + MessageFormat.RESET + " " + s.replace("\n", ""));
+            return false;
+        }
+        return true;
+    }
+
+}
diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/JunitTestRunner.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/testing/JunitTestRunner.java
@@ -196,7 +196,7 @@ public FilterResult apply(TestDescriptor testDescriptor) {
                     listener.runStarted(toRun);
                 }
                 log.debug("Starting test run with " + testPlan.countTestIdentifiers((s) -> true) + " tests");
-                QuarkusConsole.INSTANCE.addOutputFilter(logHandler);
+                QuarkusConsole.addOutputFilter(logHandler);
 
                 final Deque<Set<String>> touchedClasses = new LinkedBlockingDeque<>();
                 Map<TestIdentifier, Long> startTimes = new HashMap<>();

diff --git a/core/devmode-spi/src/main/java/io/quarkus/dev/console/QuarkusConsole.java b/core/devmode-spi/src/main/java/io/quarkus/dev/console/QuarkusConsole.java
@@ -120,4 +120,8 @@ protected boolean shouldWrite(boolean errorStream, String s) {
     public boolean isInputSupported() {
         return true;
     }
+
+    public boolean isAnsiSupported() {
+        return false;
+    }
 }
diff --git a/...src/main/java/io/quarkus/apicurio/registry/avro/DevServicesApicurioRegistryProcessor.java b/...src/main/java/io/quarkus/apicurio/registry/avro/DevServicesApicurioRegistryProcessor.java
@@ -20,7 +20,10 @@
 import io.quarkus.deployment.builditem.DevServicesConfigResultBuildItem;
 import io.quarkus.deployment.builditem.DevServicesSharedNetworkBuildItem;
 import io.quarkus.deployment.builditem.LaunchModeBuildItem;
+import io.quarkus.deployment.console.ConsoleInstalledBuildItem;
+import io.quarkus.deployment.console.StartupLogCompressor;
 import io.quarkus.deployment.dev.devservices.GlobalDevServicesConfig;
+import io.quarkus.deployment.logging.LoggingSetupBuildItem;
 import io.quarkus.devservices.common.ContainerLocator;
 import io.quarkus.runtime.LaunchMode;
 import io.quarkus.runtime.configuration.ConfigUtils;
@@ -57,7 +60,9 @@ public class DevServicesApicurioRegistryProcessor {
     public void startApicurioRegistryDevService(LaunchModeBuildItem launchMode,
             ApicurioRegistryDevServicesBuildTimeConfig apicurioRegistryDevServices,
             Optional<DevServicesSharedNetworkBuildItem> devServicesSharedNetworkBuildItem,
-            BuildProducer<DevServicesConfigResultBuildItem> devServicesConfiguration) {
+            BuildProducer<DevServicesConfigResultBuildItem> devServicesConfiguration,
+            Optional<ConsoleInstalledBuildItem> consoleInstalledBuildItem,
+            LoggingSetupBuildItem loggingSetupBuildItem) {
 
         ApicurioRegistryDevServiceCfg configuration = getConfiguration(apicurioRegistryDevServices);
 
@@ -69,11 +74,19 @@ public void startApicurioRegistryDevService(LaunchModeBuildItem launchMode,
             shutdownApicurioRegistry();
             cfg = null;
         }
-
-        ApicurioRegistry apicurioRegistry = startApicurioRegistry(configuration, launchMode,
-                devServicesSharedNetworkBuildItem.isPresent());
-        if (apicurioRegistry == null) {
-            return;
+        ApicurioRegistry apicurioRegistry;
+        StartupLogCompressor compressor = new StartupLogCompressor("Apicurio Registry Dev Services Starting:",
+                consoleInstalledBuildItem, loggingSetupBuildItem);
+        try {
+            apicurioRegistry = startApicurioRegistry(configuration, launchMode,
+                    devServicesSharedNetworkBuildItem.isPresent());
+            if (apicurioRegistry == null) {
+                return;
+            }
+            compressor.close();
+        } catch (Throwable t) {
+            compressor.closeAndDumpCaptured();
+            throw new RuntimeException(t);
         }
 
         cfg = configuration;

diff --git a/...ain/java/io/quarkus/datasource/deployment/devservices/DevServicesDatasourceProcessor.java b/...ain/java/io/quarkus/datasource/deployment/devservices/DevServicesDatasourceProcessor.java
@@ -27,7 +27,10 @@
 import io.quarkus.deployment.annotations.BuildStep;
 import io.quarkus.deployment.builditem.DevServicesConfigResultBuildItem;
 import io.quarkus.deployment.builditem.LaunchModeBuildItem;
+import io.quarkus.deployment.console.ConsoleInstalledBuildItem;
+import io.quarkus.deployment.console.StartupLogCompressor;
 import io.quarkus.deployment.dev.devservices.GlobalDevServicesConfig;
+import io.quarkus.deployment.logging.LoggingSetupBuildItem;
 import io.quarkus.deployment.pkg.builditem.CurateOutcomeBuildItem;
 import io.quarkus.runtime.LaunchMode;
 
@@ -50,7 +53,9 @@ DevServicesDatasourceResultBuildItem launchDatabases(CurateOutcomeBuildItem cura
             DataSourcesBuildTimeConfig dataSourceBuildTimeConfig,
             LaunchModeBuildItem launchMode,
             List<DevServicesDatasourceConfigurationHandlerBuildItem> configurationHandlerBuildItems,
-            BuildProducer<DevServicesConfigResultBuildItem> devServicesResultBuildItemBuildProducer) {
+            BuildProducer<DevServicesConfigResultBuildItem> devServicesResultBuildItemBuildProducer,
+            Optional<ConsoleInstalledBuildItem> consoleInstalledBuildItem,
+            LoggingSetupBuildItem loggingSetupBuildItem) {
         //figure out if we need to shut down and restart existing databases
         //if not and the DB's have already started we just return
         if (databases != null) {
@@ -111,60 +116,68 @@ DevServicesDatasourceResultBuildItem launchDatabases(CurateOutcomeBuildItem cura
         Map<String, DevServicesDatasourceProvider> devDBProviderMap = devDBProviders.stream()
                 .collect(Collectors.toMap(DevServicesDatasourceProviderBuildItem::getDatabase,
                         DevServicesDatasourceProviderBuildItem::getDevServicesProvider));
-
-        defaultResult = startDevDb(null, curateOutcomeBuildItem, installedDrivers,
-                !dataSourceBuildTimeConfig.namedDataSources.isEmpty(),
-                devDBProviderMap,
-                dataSourceBuildTimeConfig.defaultDataSource,
-                configHandlersByDbType, propertiesMap, closeableList, launchMode.getLaunchMode());
-        List<DevServicesConfigResultBuildItem> dbConfig = new ArrayList<>();
-        if (defaultResult != null) {
-            for (Map.Entry<String, String> i : defaultResult.getConfigProperties().entrySet()) {
-                dbConfig.add(new DevServicesConfigResultBuildItem(i.getKey(), i.getValue()));
-            }
-        }
-        for (Map.Entry<String, DataSourceBuildTimeConfig> entry : dataSourceBuildTimeConfig.namedDataSources.entrySet()) {
-            DevServicesDatasourceResultBuildItem.DbResult result = startDevDb(entry.getKey(), curateOutcomeBuildItem,
-                    installedDrivers, true,
-                    devDBProviderMap, entry.getValue(), configHandlersByDbType, propertiesMap, closeableList,
-                    launchMode.getLaunchMode());
-            if (result != null) {
-                namedResults.put(entry.getKey(), result);
-                for (Map.Entry<String, String> i : result.getConfigProperties().entrySet()) {
+        StartupLogCompressor compressor = new StartupLogCompressor("Database Starting:", consoleInstalledBuildItem,
+                loggingSetupBuildItem);
+        try {
+            defaultResult = startDevDb(null, curateOutcomeBuildItem, installedDrivers,
+                    !dataSourceBuildTimeConfig.namedDataSources.isEmpty(),
+                    devDBProviderMap,
+                    dataSourceBuildTimeConfig.defaultDataSource,
+                    configHandlersByDbType, propertiesMap, closeableList, launchMode.getLaunchMode());
+            List<DevServicesConfigResultBuildItem> dbConfig = new ArrayList<>();
+            if (defaultResult != null) {
+                for (Map.Entry<String, String> i : defaultResult.getConfigProperties().entrySet()) {
                     dbConfig.add(new DevServicesConfigResultBuildItem(i.getKey(), i.getValue()));
                 }
             }
-        }
-        for (DevServicesConfigResultBuildItem i : dbConfig) {
-            devServicesResultBuildItemBuildProducer
-                    .produce(i);
-        }
+            for (Map.Entry<String, DataSourceBuildTimeConfig> entry : dataSourceBuildTimeConfig.namedDataSources.entrySet()) {
+                DevServicesDatasourceResultBuildItem.DbResult result = startDevDb(entry.getKey(), curateOutcomeBuildItem,
+                        installedDrivers, true,
+                        devDBProviderMap, entry.getValue(), configHandlersByDbType, propertiesMap, closeableList,
+                        launchMode.getLaunchMode());
+                if (result != null) {
+                    namedResults.put(entry.getKey(), result);
+                    for (Map.Entry<String, String> i : result.getConfigProperties().entrySet()) {
+                        dbConfig.add(new DevServicesConfigResultBuildItem(i.getKey(), i.getValue()));
+                    }
+                }
+            }
+            for (DevServicesConfigResultBuildItem i : dbConfig) {
+                devServicesResultBuildItemBuildProducer
+                        .produce(i);
+            }
 
-        if (first) {
-            first = false;
-            Runnable closeTask = new Runnable() {
-                @Override
-                public void run() {
-                    if (databases != null) {
-                        for (Closeable i : databases) {
-                            try {
-                                i.close();
-                            } catch (Throwable t) {
-                                log.error("Failed to stop database", t);
+            if (first) {
+                first = false;
+                Runnable closeTask = new Runnable() {
+                    @Override
+                    public void run() {
+                        if (databases != null) {
+                            for (Closeable i : databases) {
+                                try {
+                                    i.close();
+                                } catch (Throwable t) {
+                                    log.error("Failed to stop database", t);
+                                }
                             }
                         }
+                        first = true;
+                        databases = null;
+                        cachedProperties = null;
                     }
-                    first = true;
-                    databases = null;
-                    cachedProperties = null;
-                }
-            };
-            QuarkusClassLoader cl = (QuarkusClassLoader) Thread.currentThread().getContextClassLoader();
-            ((QuarkusClassLoader) cl.parent()).addCloseTask(closeTask);
+                };
+                QuarkusClassLoader cl = (QuarkusClassLoader) Thread.currentThread().getContextClassLoader();
+                ((QuarkusClassLoader) cl.parent()).addCloseTask(closeTask);
+            }
+            databases = closeableList;
+            cachedProperties = propertiesMap;
+            compressor.close();
+            log.info("Dev Services for datasources started.");
+            return new DevServicesDatasourceResultBuildItem(defaultResult, namedResults);
+        } catch (Throwable t) {
+            compressor.closeAndDumpCaptured();
+            throw new RuntimeException(t);
         }
-        databases = closeableList;
-        cachedProperties = propertiesMap;
-        return new DevServicesDatasourceResultBuildItem(defaultResult, namedResults);
     }
 
     private DevServicesDatasourceResultBuildItem.DbResult startDevDb(String dbName,