SONAR-7053 Can't activate debug logging between analysis

sonar-batch/src/main/java/org/sonar/batch/bootstrapper/Batch.java

@@ -107,7 +107,9 @@ public final class Batch {
    */
   public Batch executeTask(Map<String, String> analysisProperties, Object... components) {
     checkStarted();
+    configureTaskLogging(analysisProperties);
     bootstrapContainer.executeTask(analysisProperties, components);
+    configureLogging();
     return this;
   }
 
@@ -116,7 +118,9 @@ public final class Batch {
    */
   public Batch executeTask(Map<String, String> analysisProperties, IssueListener issueListener) {
     checkStarted();
+    configureTaskLogging(analysisProperties);
     bootstrapContainer.executeTask(analysisProperties, components, issueListener);
+    configureLogging();
     return this;
   }
 
@@ -150,6 +154,14 @@ public final class Batch {
 
   private void configureLogging() {
     if (loggingConfig != null) {
+      loggingConfig.setProperties(bootstrapProperties);
+      LoggingConfigurator.apply(loggingConfig);
+    }
+  }
+
+  private void configureTaskLogging(Map<String, String> taskProperties) {
+    if (loggingConfig != null) {
+      loggingConfig.setProperties(taskProperties, bootstrapProperties);
       LoggingConfigurator.apply(loggingConfig);
     }
   }

sonar-batch/src/main/java/org/sonar/batch/bootstrapper/LoggingConfiguration.java

@@ -21,8 +21,12 @@ package org.sonar.batch.bootstrapper;
 
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.collect.Maps;
+
 import java.util.Map;
+
+import javax.annotation.CheckForNull;
 import javax.annotation.Nullable;
+
 import org.apache.commons.lang.StringUtils;
 
 /**
@@ -60,8 +64,14 @@ public final class LoggingConfiguration {
   }
 
   public LoggingConfiguration setProperties(Map<String, String> properties) {
-    setShowSql(properties);
-    setVerbose(properties);
+    setShowSql(properties, null);
+    setVerbose(properties, null);
+    return this;
+  }
+
+  public LoggingConfiguration setProperties(Map<String, String> properties, @Nullable Map<String, String> fallback) {
+    setShowSql(properties, fallback);
+    setVerbose(properties, fallback);
     return this;
   }
 
@@ -74,16 +84,29 @@ public final class LoggingConfiguration {
     return setRootLevel(verbose ? LEVEL_ROOT_VERBOSE : LEVEL_ROOT_DEFAULT);
   }
 
-  public LoggingConfiguration setVerbose(Map<String, String> properties) {
-    String logLevel = properties.get("sonar.log.level");
-    String deprecatedProfilingLevel = properties.get("sonar.log.profilingLevel");
-    boolean verbose = "true".equals(properties.get("sonar.verbose")) ||
+  public LoggingConfiguration setVerbose(Map<String, String> props, @Nullable Map<String, String> fallback) {
+    String logLevel = getFallback("sonar.log.level", props, fallback);
+    String deprecatedProfilingLevel = getFallback("sonar.log.profilingLevel", props, fallback);
+    boolean verbose = "true".equals(getFallback("sonar.verbose", props, fallback)) ||
       "DEBUG".equals(logLevel) || "TRACE".equals(logLevel) ||
       "BASIC".equals(deprecatedProfilingLevel) || "FULL".equals(deprecatedProfilingLevel);
 
     return setVerbose(verbose);
   }
 
+  @CheckForNull
+  private static String getFallback(String key, Map<String, String> properties, @Nullable Map<String, String> fallback) {
+    if (properties.containsKey(key)) {
+      return properties.get(key);
+    }
+
+    if (fallback != null) {
+      return fallback.get(key);
+    }
+
+    return null;
+  }
+
   public LoggingConfiguration setRootLevel(String level) {
     return addSubstitutionVariable(PROPERTY_ROOT_LOGGER_LEVEL, level);
   }
@@ -92,9 +115,9 @@ public final class LoggingConfiguration {
     return addSubstitutionVariable(PROPERTY_SQL_LOGGER_LEVEL, showSql ? "TRACE" : "WARN");
   }
 
-  public LoggingConfiguration setShowSql(Map<String, String> properties) {
-    String logLevel = properties.get("sonar.log.level");
-    String deprecatedProfilingLevel = properties.get("sonar.log.profilingLevel");
+  public LoggingConfiguration setShowSql(Map<String, String> properties, @Nullable Map<String, String> fallback) {
+    String logLevel = getFallback("sonar.log.level", properties, fallback);
+    String deprecatedProfilingLevel = getFallback("sonar.log.profilingLevel", properties, fallback);
     boolean sql = "TRACE".equals(logLevel) || "FULL".equals(deprecatedProfilingLevel);
 
     return setShowSql(sql);

sonar-batch/src/main/java/org/sonar/batch/bootstrapper/LoggingConfigurator.java

@@ -29,6 +29,8 @@ import org.slf4j.LoggerFactory;
 import org.sonar.core.config.Logback;
 
 public class LoggingConfigurator {
+  private static final String CUSTOM_APPENDER_NAME = "custom_stream";
+
   private LoggingConfigurator() {
   }
 
@@ -55,17 +57,18 @@ public class LoggingConfigurator {
 
   private static void setCustomRootAppender(LoggingConfiguration conf) {
     Logger logger = (Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
-    String pattern = StringUtils.defaultIfBlank(conf.getSubstitutionVariables().get(LoggingConfiguration.PROPERTY_FORMAT), LoggingConfiguration.FORMAT_DEFAULT);
     String level = StringUtils.defaultIfBlank(conf.getSubstitutionVariables().get(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL), LoggingConfiguration.LEVEL_ROOT_DEFAULT);
 
-    logger.detachAndStopAllAppenders();
-    logger.addAppender(createAppender(pattern, conf.getLogOutput()));
+    if (logger.getAppender(CUSTOM_APPENDER_NAME) == null) {
+      logger.detachAndStopAllAppenders();
+      logger.addAppender(createAppender(conf.getLogOutput()));
+    }
     logger.setLevel(Level.toLevel(level));
   }
 
-  private static Appender<ILoggingEvent> createAppender(String pattern, LogOutput target) {
+  private static Appender<ILoggingEvent> createAppender(LogOutput target) {
     LogCallbackAppender appender = new LogCallbackAppender(target);
-    appender.setName("custom_stream");
+    appender.setName(CUSTOM_APPENDER_NAME);
     appender.start();
 
     return appender;

sonar-batch/src/test/java/org/sonar/batch/bootstrapper/LoggingConfigurationTest.java

@@ -40,6 +40,37 @@ public class LoggingConfigurationTest {
       .getSubstitutionVariable(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL)).isEqualTo("ERROR");
   }
 
+  @Test
+  public void testSetVerboseAnalysis() {
+    Map<String, String> globalProps = Maps.newHashMap();
+    LoggingConfiguration conf = new LoggingConfiguration(null).setProperties(globalProps);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL)).isEqualTo(LoggingConfiguration.LEVEL_ROOT_DEFAULT);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_SQL_LOGGER_LEVEL)).isEqualTo("WARN");
+
+    Map<String, String> analysisProperties = Maps.newHashMap();
+    analysisProperties.put("sonar.verbose", "true");
+
+    conf.setProperties(analysisProperties, globalProps);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL)).isEqualTo(LoggingConfiguration.LEVEL_ROOT_VERBOSE);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_SQL_LOGGER_LEVEL)).isEqualTo("WARN");
+  }
+
+  @Test
+  public void testOverrideVerbose() {
+    Map<String, String> globalProps = Maps.newHashMap();
+    globalProps.put("sonar.verbose", "true");
+    LoggingConfiguration conf = new LoggingConfiguration(null).setProperties(globalProps);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL)).isEqualTo(LoggingConfiguration.LEVEL_ROOT_VERBOSE);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_SQL_LOGGER_LEVEL)).isEqualTo("WARN");
+
+    Map<String, String> analysisProperties = Maps.newHashMap();
+    analysisProperties.put("sonar.verbose", "false");
+
+    conf.setProperties(analysisProperties, globalProps);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_ROOT_LOGGER_LEVEL)).isEqualTo(LoggingConfiguration.LEVEL_ROOT_DEFAULT);
+    assertThat(conf.getSubstitutionVariable(LoggingConfiguration.PROPERTY_SQL_LOGGER_LEVEL)).isEqualTo("WARN");
+  }
+
   @Test
   public void shouldNotBeVerboseByDefault() {
     assertThat(new LoggingConfiguration(null)

sonar-batch/src/test/java/org/sonar/batch/bootstrapper/LoggingConfiguratorTest.java

@@ -111,6 +111,23 @@ public class LoggingConfiguratorTest {
     assertThat(out.size()).isEqualTo(0);
   }
 
+  @Test
+  public void testConfigureMultipleTimes() throws UnsupportedEncodingException {
+    System.setOut(new PrintStream(out, false, StandardCharsets.UTF_8.name()));
+    conf.setLogOutput(listener);
+    LoggingConfigurator.apply(conf);
+
+    Logger logger = LoggerFactory.getLogger(this.getClass());
+    logger.debug("debug");
+    assertThat(listener.msg).isNull();
+
+    conf.setVerbose(true);
+    LoggingConfigurator.apply(conf);
+
+    logger.debug("debug");
+    assertThat(listener.msg).isEqualTo("debug");
+  }
+
   @Test
   public void testFormatNoEffect() throws UnsupportedEncodingException {
     conf.setLogOutput(listener);

sonar-batch/src/test/java/org/sonar/batch/mediumtest/log/LogListenerTest.java

@@ -32,7 +32,6 @@ import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
 import org.apache.commons.io.FileUtils;
-import org.junit.After;
 import org.junit.AfterClass;
 import org.junit.Before;
 import org.junit.BeforeClass;
@@ -54,6 +53,7 @@ public class LogListenerTest {
 
   private Pattern simpleTimePattern = Pattern.compile("\\d{2}:\\d{2}:\\d{2}");
   private List<LogEvent> logOutput;
+  private StringBuilder logOutputStr;
   private ByteArrayOutputStream stdOutTarget = new ByteArrayOutputStream();
   private ByteArrayOutputStream stdErrTarget = new ByteArrayOutputStream();
   private static PrintStream savedStdOut;
@@ -91,6 +91,7 @@ public class LogListenerTest {
     System.setErr(new PrintStream(stdErrTarget));
     // logger from the batch might write to it asynchronously
     logOutput = Collections.synchronizedList(new LinkedList<LogEvent>());
+    logOutputStr = new StringBuilder();
     tester.start();
 
     baseDir = temp.getRoot();
@@ -121,9 +122,28 @@ public class LogListenerTest {
     assertThat(matcher.find()).isFalse();
   }
 
-  @After
-  public void stop() {
+  @Test
+  public void testChangeLogForAnalysis() throws IOException, InterruptedException {
+    File srcDir = new File(baseDir, "src");
+    srcDir.mkdir();
+
+    File xooFile = new File(srcDir, "sample.xoo");
+    FileUtils.write(xooFile, "Sample xoo\ncontent");
+
+    tester.newTask()
+      .properties(builder
+        .put("sonar.sources", "src")
+        .put("sonar.verbose", "true")
+        .build())
+      .start();
+
     tester.stop();
+    for (LogEvent e : logOutput) {
+      savedStdOut.println("[captured]" + e.level + " " + e.msg);
+    }
+
+    // only done in DEBUG during analysis
+    assertThat(logOutputStr.toString()).contains("Post-jobs : ");
   }
 
   @Test
@@ -139,6 +159,7 @@ public class LogListenerTest {
         .put("sonar.sources", "src")
         .build())
       .start();
+    tester.stop();
 
     assertNoStdOutput();
     assertThat(logOutput).isNotEmpty();
@@ -163,6 +184,7 @@ public class LogListenerTest {
         .put("sonar.sources", "src")
         .build())
       .start();
+    tester.stop();
 
     assertNoStdOutput();
 
@@ -178,6 +200,7 @@ public class LogListenerTest {
     @Override
     public void log(String msg, Level level) {
       logOutput.add(new LogEvent(msg, level));
+      logOutputStr.append(msg).append("\n");
     }
   }