Use SLF4J for runtime diagnostics

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

@@ -44,6 +44,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;
@@ -63,6 +65,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";
@@ -410,7 +414,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/groovy/grails/build/logging/GrailsConsoleLoggingSpec.groovy

@@ -0,0 +1,115 @@
+/*
+ *  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.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 = """\
+            -cp
+            ${testRuntimeClasspath(apiOnly)}
+            ${GrailsConsoleLoggingSpec.name}
+            ${apiOnly}
+            """.stripIndent().trim()
+        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)
+    }
+
+    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,11 +21,10 @@
 import groovy.lang.GroovySystem;
 import groovy.lang.MetaClassRegistry;
 
-import org.apache.commons.logging.Log;
-import org.apache.commons.logging.LogFactory;
-
 import org.springframework.context.ApplicationContext;
 import org.springframework.core.io.Resource;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import grails.core.GrailsApplication;
 import grails.plugins.DefaultGrailsPluginManager;
@@ -43,7 +42,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 +109,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 +128,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);
     }
 }

grails-core/src/test/groovy/org/grails/plugins/ProfilingGrailsPluginManagerSpec.groovy

@@ -0,0 +1,84 @@
+/*
+ *  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 org.grails.plugins
+
+import grails.core.DefaultGrailsApplication
+import org.apache.grails.core.plugins.DefaultPluginDiscovery
+import org.apache.grails.core.plugins.PluginDiscovery
+import org.springframework.context.support.GenericApplicationContext
+import org.springframework.core.env.StandardEnvironment
+import spock.lang.Specification
+
+class ProfilingGrailsPluginManagerSpec extends Specification {
+
+    void "plugin loading emits INFO profiling messages instead of standard output"() {
+        given:
+        def application = new DefaultGrailsApplication()
+        application.mainContext = new GenericApplicationContext()
+        def discovery = new DefaultPluginDiscovery(new Class<?>[0])
+        discovery.loadPluginsFromClasspath = false
+        discovery.init(new StandardEnvironment())
+        def manager = new ProfilingGrailsPluginManager(application, discovery)
+        def originalOut = System.out
+        def originalErr = System.err
+        def capturedOut = new ByteArrayOutputStream()
+        def capturedErr = new ByteArrayOutputStream()
+        System.setOut(new PrintStream(capturedOut, true))
+        System.setErr(new PrintStream(capturedErr, true))
+
+        when:
+        manager.loadPlugins()
+
+        then:
+        !capturedOut.toString().contains('Loading plugins')
+        capturedErr.toString().contains('INFO grails.plugins.DefaultGrailsPluginManager - Loading plugins started')
+        capturedErr.toString() ==~ /(?s).*INFO grails\.plugins\.DefaultGrailsPluginManager - Loading plugins took \d+.*/
+
+        cleanup:
+        System.setOut(originalOut)
+        System.setErr(originalErr)
+    }
+
+    void "deprecated constructors log their warning in the historical category"() {
+        given:
+        def application = new DefaultGrailsApplication()
+        def applicationContext = new GenericApplicationContext()
+        def discovery = Mock(PluginDiscovery)
+        applicationContext.beanFactory.registerSingleton(PluginDiscovery.BEAN_NAME, discovery)
+        applicationContext.refresh()
+        application.mainContext = applicationContext
+        def originalErr = System.err
+        def capturedErr = new ByteArrayOutputStream()
+        System.setErr(new PrintStream(capturedErr, true))
+
+        when:
+        def manager = new ProfilingGrailsPluginManager(new Class<?>[0], application)
+
+        then:
+        manager
+        1 * discovery.reset()
+        1 * discovery.setPluginClasses(_)
+        1 * discovery.init(_)
+        capturedErr.toString().contains('WARN grails.plugins.DefaultGrailsPluginManager - Using deprecated DefaultGrailsPluginManager constructor.')
+
+        cleanup:
+        System.setErr(originalErr)
+        applicationContext.close()
+    }
+}

grails-data-hibernate5/grails-plugin/build.gradle

@@ -82,11 +82,12 @@ dependencies {
     }
     testRuntimeOnly 'org.springframework:spring-aop'
     testRuntimeOnly 'org.springframework:spring-expression'
+    testRuntimeOnly 'org.slf4j:slf4j-simple'
     testRuntimeOnly 'org.yaml:snakeyaml'
 }
 
 apply {
     from rootProject.layout.projectDirectory.file('gradle/hibernate5-test-config.gradle')
     from rootProject.layout.projectDirectory.file('gradle/docs-config.gradle')
     from rootProject.layout.projectDirectory.file('gradle/grails-extension-gradle-config.gradle')
-}
+}