Use SLF4J for runtime diagnostics

grails-bootstrap/src/cli/groovy/grails/build/logging/GrailsConsole.java

@@ -43,6 +43,8 @@
 import org.jline.reader.impl.history.DefaultHistory;
 import org.jline.terminal.Terminal;
 import org.jline.terminal.TerminalBuilder;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import grails.util.Environment;
 import org.grails.build.logging.GrailsConsoleErrorPrintStream;
@@ -62,6 +64,8 @@
  */
 public class GrailsConsole implements ConsoleLogger {
 
+    private static final Logger LOG = LoggerFactory.getLogger(GrailsConsole.class);
+
     private static GrailsConsole instance;
 
     public static final String ENABLE_TERMINAL = "grails.console.enable.terminal";
@@ -442,7 +446,11 @@ public static GrailsConsole createInstance() throws IOException {
                 Class<? extends GrailsConsole> klass = (Class<? extends GrailsConsole>) Class.forName(className);
                 return klass.getDeclaredConstructor().newInstance();
             } catch (Exception e) {
-                e.printStackTrace();
+                if (LOG.isErrorEnabled()) {
+                    LOG.error("Unable to create configured Grails console " + className, e);
+                } else {
+                    e.printStackTrace();
+                }
             }
         }
         return new GrailsConsole();

grails-bootstrap/src/test-cli/groovy/grails/build/logging/GrailsConsoleLoggingSpec.groovy

@@ -0,0 +1,122 @@
+/*
+ *  Licensed to the Apache Software Foundation (ASF) under one
+ *  or more contributor license agreements.  See the NOTICE file
+ *  distributed with this work for additional information
+ *  regarding copyright ownership.  The ASF licenses this file
+ *  to you under the Apache License, Version 2.0 (the
+ *  "License"); you may not use this file except in compliance
+ *  with the License.  You may obtain a copy of the License at
+ *
+ *    https://www.apache.org/licenses/LICENSE-2.0
+ *
+ *  Unless required by applicable law or agreed to in writing,
+ *  software distributed under the License is distributed on an
+ *  "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ *  KIND, either express or implied.  See the License for the
+ *  specific language governing permissions and limitations
+ *  under the License.
+ */
+package grails.build.logging
+
+import java.lang.management.ManagementFactory
+import java.util.concurrent.TimeUnit
+
+import org.slf4j.LoggerFactory
+import spock.lang.Specification
+import spock.lang.TempDir
+
+class GrailsConsoleLoggingSpec extends Specification {
+
+    @TempDir
+    File tempDir
+
+    void "invalid configured console failure is visible with #loggingDescription"() {
+        given:
+        String output = runFixture(apiOnly)
+
+        expect:
+        apiOnly ? output.contains('ClassNotFoundException: invalid.console.ClassName') :
+            output.count('Unable to create configured Grails console invalid.console.ClassName') == 1
+        output.readLines().last() == 'verified'
+
+        where:
+        apiOnly | loggingDescription
+        true    | 'an API-only SLF4J classpath'
+        false   | 'an ERROR-capable SLF4J provider'
+    }
+
+    private String runFixture(boolean apiOnly) {
+        File argumentsFile = new File(tempDir, "grails-console-${apiOnly}.args")
+        File outputFile = new File(tempDir, "grails-console-${apiOnly}.output")
+        argumentsFile.text = (jacocoAgentArguments() + [
+            '-cp',
+            testRuntimeClasspath(apiOnly),
+            GrailsConsoleLoggingSpec.name,
+            apiOnly as String
+        ]).join('\n')
+        Process process = new ProcessBuilder(
+            new File(System.getProperty('java.home'), 'bin/java').absolutePath,
+            "@${argumentsFile.absolutePath}"
+        ).redirectErrorStream(true).redirectOutput(outputFile).start()
+        process.outputStream.close()
+        try {
+            awaitProcess(process, 'GrailsConsole logging fixture')
+            String output = outputFile.getText('UTF-8').trim()
+            assert process.exitValue() == 0 : output
+            output
+        } finally {
+            if (process.isAlive()) {
+                process.destroyForcibly()
+                process.waitFor(5, TimeUnit.SECONDS)
+            }
+        }
+    }
+
+    private static void awaitProcess(Process process, String fixtureName) {
+        if (process.waitFor(30, TimeUnit.SECONDS)) {
+            return
+        }
+        process.destroyForcibly()
+        if (!process.waitFor(5, TimeUnit.SECONDS)) {
+            throw new AssertionError("${fixtureName} did not terminate after timing out")
+        }
+        throw new AssertionError("${fixtureName} timed out after 30 seconds")
+    }
+
+    private static String testRuntimeClasspath(boolean apiOnly) {
+        String[] entries = System.getProperty('java.class.path').split(File.pathSeparator)
+        if (!apiOnly) {
+            return entries.join(File.pathSeparator)
+        }
+        entries.findAll { !it.contains('slf4j-simple') && !it.contains('logback-classic') }.join(File.pathSeparator)
+    }
+
+    private static List<String> jacocoAgentArguments() {
+        ManagementFactory.runtimeMXBean.inputArguments.findAll {
+            it.startsWith('-javaagent:') && it.contains('jacoco')
+        }
+    }
+
+    static void main(String[] args) {
+        boolean apiOnly = Boolean.parseBoolean(args[0])
+        System.setProperty('grails.console.class', 'invalid.console.ClassName')
+        System.setProperty(GrailsConsole.ENABLE_INTERACTIVE, 'false')
+        System.setProperty(GrailsConsole.ENABLE_TERMINAL, 'false')
+        GrailsConsole console
+        Throwable failure
+        try {
+            assert LoggerFactory.getLogger(GrailsConsole).errorEnabled == !apiOnly
+            console = GrailsConsole.createInstance()
+            assert console.class == GrailsConsole
+        } catch (Throwable throwable) {
+            failure = throwable
+        } finally {
+            console?.restoreOriginalSystemOutAndErr()
+        }
+        if (failure != null) {
+            failure.printStackTrace()
+            System.exit(1)
+        }
+        println 'verified'
+    }
+}

grails-core/src/main/groovy/org/grails/plugins/ProfilingGrailsPluginManager.java

@@ -21,8 +21,8 @@
 import groovy.lang.GroovySystem;
 import groovy.lang.MetaClassRegistry;
 
-import org.apache.commons.logging.Log;
-import org.apache.commons.logging.LogFactory;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import org.springframework.context.ApplicationContext;
 import org.springframework.core.io.Resource;
@@ -43,7 +43,7 @@
  */
 public class ProfilingGrailsPluginManager extends DefaultGrailsPluginManager {
 
-    private static final Log LOG = LogFactory.getLog(DefaultGrailsPluginManager.class);
+    private static final Logger LOG = LoggerFactory.getLogger(DefaultGrailsPluginManager.class);
 
     public ProfilingGrailsPluginManager(GrailsApplication application, PluginDiscovery pluginDiscovery) {
         super(application, pluginDiscovery);
@@ -110,15 +110,15 @@ private static PluginDiscovery resolveAndResetDiscovery(GrailsApplication applic
     @Override
     public void loadPlugins() throws PluginException {
         long time = System.currentTimeMillis();
-        System.out.println("Loading plugins started");
+        LOG.info("Loading plugins started");
         super.loadPlugins();
-        System.out.println("Loading plugins took " + (System.currentTimeMillis() - time));
+        LOG.info("Loading plugins took {}", System.currentTimeMillis() - time);
     }
 
     @Override
     public void doDynamicMethods() {
         long time = System.currentTimeMillis();
-        System.out.println("doWithDynamicMethods started");
+        LOG.info("doWithDynamicMethods started");
         checkInitialised();
         // remove common meta classes just to be sure
         MetaClassRegistry registry = GroovySystem.getMetaClassRegistry();
@@ -129,57 +129,57 @@ public void doDynamicMethods() {
             if (plugin.supportsCurrentScopeAndEnvironment()) {
                 try {
                     long pluginTime = System.currentTimeMillis();
-                    System.out.println("doWithDynamicMethods for plugin [" + plugin.getName() + "] started");
+                    LOG.info("doWithDynamicMethods for plugin [{}] started", plugin.getName());
 
                     plugin.doWithDynamicMethods(applicationContext);
 
-                    System.out.println("doWithDynamicMethods for plugin [" + plugin.getName() + "] took " + (System.currentTimeMillis() - pluginTime));
+                    LOG.info("doWithDynamicMethods for plugin [{}] took {}", plugin.getName(), System.currentTimeMillis() - pluginTime);
                 } catch (Throwable t) {
                     throw new GrailsConfigurationException("Error configuring dynamic methods for plugin " + plugin + ": " + t.getMessage(), t);
                 }
             }
         }
-        System.out.println("doWithDynamicMethods took " + (System.currentTimeMillis() - time));
+        LOG.info("doWithDynamicMethods took {}", System.currentTimeMillis() - time);
     }
 
     @Override
     public void doRuntimeConfiguration(RuntimeSpringConfiguration springConfig) {
         long time = System.currentTimeMillis();
 
-        System.out.println("doWithSpring started");
+        LOG.info("doWithSpring started");
         checkInitialised();
         for (GrailsPlugin plugin : getAllPlugins()) {
             if (plugin.supportsCurrentScopeAndEnvironment()) {
                 long pluginTime = System.currentTimeMillis();
-                System.out.println("doWithSpring for plugin [" + plugin.getName() + "] started");
+                LOG.info("doWithSpring for plugin [{}] started", plugin.getName());
                 plugin.doWithRuntimeConfiguration(springConfig);
-                System.out.println("doWithSpring for plugin [" + plugin.getName() + "] took " + (System.currentTimeMillis() - pluginTime));
+                LOG.info("doWithSpring for plugin [{}] took {}", plugin.getName(), System.currentTimeMillis() - pluginTime);
             }
         }
-        System.out.println("doWithSpring took " + (System.currentTimeMillis() - time));
+        LOG.info("doWithSpring took {}", System.currentTimeMillis() - time);
     }
 
     @Override
     public void doPostProcessing(ApplicationContext ctx) {
         long time = System.currentTimeMillis();
-        System.out.println("doWithApplicationContext started");
+        LOG.info("doWithApplicationContext started");
         checkInitialised();
         for (GrailsPlugin plugin : getAllPlugins()) {
             if (plugin.supportsCurrentScopeAndEnvironment()) {
                 long pluginTime = System.currentTimeMillis();
-                System.out.println("doWithApplicationContext for plugin [" + plugin.getName() + "] started");
+                LOG.info("doWithApplicationContext for plugin [{}] started", plugin.getName());
                 plugin.doWithApplicationContext(ctx);
-                System.out.println("doWithApplicationContext for plugin [" + plugin.getName() + "] took " + (System.currentTimeMillis() - pluginTime));
+                LOG.info("doWithApplicationContext for plugin [{}] took {}", plugin.getName(), System.currentTimeMillis() - pluginTime);
             }
         }
-        System.out.println("doWithApplicationContext took " + (System.currentTimeMillis() - time));
+        LOG.info("doWithApplicationContext took {}", System.currentTimeMillis() - time);
     }
 
     @Override
     public void doArtefactConfiguration() {
         long time = System.currentTimeMillis();
-        System.out.println("doArtefactConfiguration started");
+        LOG.info("doArtefactConfiguration started");
         super.doArtefactConfiguration();
-        System.out.println("doArtefactConfiguration took " + (System.currentTimeMillis() - time));
+        LOG.info("doArtefactConfiguration took {}", System.currentTimeMillis() - time);
     }
 }