SONAR-13125 fixed an issue where some startup logs were not always appended to sonar.log

6 files changed, 167 insertions, 35 deletions

diff --git a/server/sonar-main/src/main/java/org/sonar/application/AppLogging.java b/server/sonar-main/src/main/java/org/sonar/application/AppLogging.java
index 946ccd5c141..87e26824b25 100644
--- a/server/sonar-main/src/main/java/org/sonar/application/AppLogging.java
+++ b/server/sonar-main/src/main/java/org/sonar/application/AppLogging.java
@@ -38,6 +38,7 @@ import org.sonar.process.logging.RootLoggerConfig;
 
 import static org.slf4j.Logger.ROOT_LOGGER_NAME;
 import static org.sonar.application.process.StreamGobbler.LOGGER_GOBBLER;
+import static org.sonar.application.process.StreamGobbler.LOGGER_STARTUP;
 import static org.sonar.process.ProcessProperties.Property.CLUSTER_ENABLED;
 import static org.sonar.process.ProcessProperties.Property.CLUSTER_NODE_NAME;
 import static org.sonar.process.logging.RootLoggerConfig.newRootLoggerConfigBuilder;
@@ -181,20 +182,22 @@ public class AppLogging {
    * printing to sonar.log must be done at logback level.
    */
   private void configureWithLogbackWritingToFile(LoggerContext ctx) {
-    // configure all logs (ie. root logger) to be written to sonar.log and also to the console with formatting
-    // in practice, this will be only APP's own logs as logs from sub processes LOGGER_GOBBLER and LOGGER_GOBBLER
-    // is configured below to be detached from root
-    // so, this will make all APP's log to be both written to sonar.log and visible in the console
-    configureRootWithLogbackWritingToFile(ctx);
+    Logger rootLogger = ctx.getLogger(ROOT_LOGGER_NAME);
+    Encoder<ILoggingEvent> encoder = helper.createEncoder(appSettings.getProps(), rootLoggerConfig, ctx);
+    FileAppender<ILoggingEvent> fileAppender = helper.newFileAppender(ctx, appSettings.getProps(), rootLoggerConfig, encoder);
+    rootLogger.addAppender(fileAppender);
+    rootLogger.addAppender(createAppConsoleAppender(ctx, encoder));
 
-    // if option -Dsonar.log.console=true has been set, sub processes will write their logs to their own files but also
-    // copy them to their System.out.
-    // otherwise, the only logs to be expected in LOGGER_GOBBLER are those before logback is setup in subprocesses or
-    // when their JVM crashes
-    // they must be printed to App's System.out as is (as they are already formatted)
-    // logger is configured to be non additive as we don't want these logs to be written to sonar.log and duplicated in
-    // the console (with an incorrect formatting)
     configureGobbler(ctx);
+
+    configureStartupLogger(ctx, fileAppender, encoder);
+  }
+
+  private void configureStartupLogger(LoggerContext ctx, FileAppender<ILoggingEvent> fileAppender, Encoder<ILoggingEvent> encoder) {
+    Logger startupLogger = ctx.getLogger(LOGGER_STARTUP);
+    startupLogger.setAdditive(false);
+    startupLogger.addAppender(fileAppender);
+    startupLogger.addAppender(helper.newConsoleAppender(ctx, GOBBLER_PLAIN_CONSOLE, encoder));
   }
 
   /**
@@ -220,14 +223,6 @@ public class AppLogging {
     configureGobbler(ctx);
   }
 
-  private void configureRootWithLogbackWritingToFile(LoggerContext ctx) {
-    Logger rootLogger = ctx.getLogger(ROOT_LOGGER_NAME);
-    Encoder<ILoggingEvent> encoder = helper.createEncoder(appSettings.getProps(), rootLoggerConfig, ctx);
-    FileAppender<ILoggingEvent> fileAppender = helper.newFileAppender(ctx, appSettings.getProps(), rootLoggerConfig, encoder);
-    rootLogger.addAppender(fileAppender);
-    rootLogger.addAppender(createAppConsoleAppender(ctx, encoder));
-  }
-
   /**
    * Configure the logger to which logs from sub processes are written to
    * (called {@link StreamGobbler#LOGGER_GOBBLER}) by {@link StreamGobbler},
diff --git a/server/sonar-main/src/main/java/org/sonar/application/SchedulerImpl.java b/server/sonar-main/src/main/java/org/sonar/application/SchedulerImpl.java
index 703aba77053..3e4b2cdb72e 100644
--- a/server/sonar-main/src/main/java/org/sonar/application/SchedulerImpl.java
+++ b/server/sonar-main/src/main/java/org/sonar/application/SchedulerImpl.java
@@ -104,6 +104,7 @@ public class SchedulerImpl implements Scheduler, ManagedProcessEventListener, Pr
         .setWatcherDelayMs(processWatcherDelayMs)
         .setStopTimeout(stopTimeoutFor(processId, settings))
         .setHardStopTimeout(HARD_STOP_TIMEOUT)
+        .setAppSettings(settings)
         .build();
       processesById.put(process.getProcessId(), process);
     }
diff --git a/server/sonar-main/src/main/java/org/sonar/application/process/ManagedProcessHandler.java b/server/sonar-main/src/main/java/org/sonar/application/process/ManagedProcessHandler.java
index cff624397ee..ef57c88b61c 100644
--- a/server/sonar-main/src/main/java/org/sonar/application/process/ManagedProcessHandler.java
+++ b/server/sonar-main/src/main/java/org/sonar/application/process/ManagedProcessHandler.java
@@ -27,6 +27,7 @@ import java.util.function.Supplier;
 import javax.annotation.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.sonar.application.config.AppSettings;
 import org.sonar.process.ProcessId;
 
 import static java.lang.String.format;
@@ -43,6 +44,7 @@ public class ManagedProcessHandler {
   private final Timeout stopTimeout;
   private final Timeout hardStopTimeout;
   private final long watcherDelayMs;
+  private final AppSettings appSettings;
 
   private ManagedProcess process;
   private StreamGobbler stdOutGobbler;
@@ -62,6 +64,7 @@ public class ManagedProcessHandler {
     this.watcherDelayMs = builder.watcherDelayMs;
     this.stopWatcher = new StopWatcher();
     this.eventWatcher = new EventWatcher();
+    this.appSettings = builder.settings;
   }
 
   public boolean start(Supplier<ManagedProcess> commandLauncher) {
@@ -77,9 +80,9 @@ public class ManagedProcessHandler {
       finalizeStop();
       throw e;
     }
-    this.stdOutGobbler = new StreamGobbler(process.getInputStream(), processId.getKey());
+    this.stdOutGobbler = new StreamGobbler(process.getInputStream(), appSettings, processId.getKey());
     this.stdOutGobbler.start();
-    this.stdErrGobbler = new StreamGobbler(process.getErrorStream(), processId.getKey());
+    this.stdErrGobbler = new StreamGobbler(process.getErrorStream(), appSettings, processId.getKey());
     this.stdErrGobbler.start();
     this.stopWatcher.start();
     this.eventWatcher.start();
@@ -302,6 +305,7 @@ public class ManagedProcessHandler {
     private long watcherDelayMs = DEFAULT_WATCHER_DELAY_MS;
     private Timeout stopTimeout;
     private Timeout hardStopTimeout;
+    private AppSettings settings;
 
     private Builder(ProcessId processId) {
       this.processId = processId;
@@ -348,6 +352,11 @@ public class ManagedProcessHandler {
       ensureHardStopTimeoutNonNull(this.hardStopTimeout);
       return new ManagedProcessHandler(this);
     }
+
+    public Builder setAppSettings(AppSettings settings) {
+      this.settings = settings;
+      return this;
+    }
   }
 
   public static final class Timeout {
diff --git a/server/sonar-main/src/main/java/org/sonar/application/process/StreamGobbler.java b/server/sonar-main/src/main/java/org/sonar/application/process/StreamGobbler.java
index 761e2ae528c..9675647631e 100644
--- a/server/sonar-main/src/main/java/org/sonar/application/process/StreamGobbler.java
+++ b/server/sonar-main/src/main/java/org/sonar/application/process/StreamGobbler.java
@@ -19,33 +19,48 @@
  */
 package org.sonar.application.process;
 
+import com.google.gson.JsonElement;
+import com.google.gson.JsonParser;
 import java.io.BufferedReader;
 import java.io.InputStream;
 import java.io.InputStreamReader;
 import javax.annotation.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.sonar.application.config.AppSettings;
+import org.sonar.process.Props;
 
 import static java.nio.charset.StandardCharsets.UTF_8;
+import static org.sonar.process.ProcessProperties.Property.LOG_JSON_OUTPUT;
 
 /**
  * Reads process output and writes to logs
  */
 public class StreamGobbler extends Thread {
-
+  public static final String LOGGER_STARTUP = "startup";
   public static final String LOGGER_GOBBLER = "gobbler";
 
+  private static final String LOGGER_STARTUP_FORMAT = String.format("[%s]", LOGGER_STARTUP);
+
+  private final AppSettings appSettings;
+
   private final InputStream is;
   private final Logger logger;
+  /*
+  This logger forwards startup logs (thanks to re-using fileappender) from subprocesses to sonar.log when running SQ not from wrapper.
+   */
+  private final Logger startupLogger;
 
-  StreamGobbler(InputStream is, String processKey) {
-    this(is, processKey, LoggerFactory.getLogger(LOGGER_GOBBLER));
+  StreamGobbler(InputStream is, AppSettings appSettings, String processKey) {
+    this(is, processKey, appSettings, LoggerFactory.getLogger(LOGGER_GOBBLER), LoggerFactory.getLogger(LOGGER_STARTUP));
   }
 
-  StreamGobbler(InputStream is, String processKey, Logger logger) {
+  StreamGobbler(InputStream is, String processKey, AppSettings appSettings, Logger logger, Logger startupLogger) {
     super(String.format("Gobbler[%s]", processKey));
     this.is = is;
     this.logger = logger;
+    this.appSettings = appSettings;
+    this.startupLogger = startupLogger;
   }
 
   @Override
@@ -53,13 +68,34 @@ public class StreamGobbler extends Thread {
     try (BufferedReader br = new BufferedReader(new InputStreamReader(is, UTF_8))) {
       String line;
       while ((line = br.readLine()) != null) {
-        logger.info(line);
+        if (line.contains(LOGGER_STARTUP)) {
+          logStartupLog(line);
+        } else {
+          logger.info(line);
+        }
       }
     } catch (Exception ignored) {
-      // ignored
     }
   }
 
+  private void logStartupLog(String line) {
+    if (isJsonLoggingEnabled()) {
+      JsonElement jsonElement = JsonParser.parseString(line);
+      if (!jsonElement.getAsJsonObject().get("logger").getAsString().equals(LOGGER_STARTUP)) {
+        // Log contains "startup" string but only in the message content. We skip.
+        return;
+      }
+      startupLogger.warn(jsonElement.getAsJsonObject().get("message").getAsString());
+    } else if (line.contains(LOGGER_STARTUP_FORMAT)) {
+      startupLogger.warn(line.substring(line.indexOf(LOGGER_STARTUP_FORMAT) + LOGGER_STARTUP_FORMAT.length() + 1));
+    }
+  }
+
+  private boolean isJsonLoggingEnabled() {
+    Props props = appSettings.getProps();
+    return props.valueAsBoolean(LOG_JSON_OUTPUT.getKey(), Boolean.parseBoolean(LOG_JSON_OUTPUT.getDefaultValue()));
+  }
+
   static void waitUntilFinish(@Nullable StreamGobbler gobbler) {
     if (gobbler != null) {
       try {
diff --git a/server/sonar-main/src/test/java/org/sonar/application/AppLoggingTest.java b/server/sonar-main/src/test/java/org/sonar/application/AppLoggingTest.java
index a5230036db5..5b9a9a57d25 100644
--- a/server/sonar-main/src/test/java/org/sonar/application/AppLoggingTest.java
+++ b/server/sonar-main/src/test/java/org/sonar/application/AppLoggingTest.java
@@ -48,6 +48,7 @@ import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 import static org.slf4j.Logger.ROOT_LOGGER_NAME;
 import static org.sonar.application.process.StreamGobbler.LOGGER_GOBBLER;
+import static org.sonar.application.process.StreamGobbler.LOGGER_STARTUP;
 import static org.sonar.process.ProcessProperties.Property.CLUSTER_ENABLED;
 import static org.sonar.process.ProcessProperties.Property.PATH_LOGS;
 
@@ -115,10 +116,10 @@ public class AppLoggingTest {
     verifySonarLogFileAppender(rootLogger.getAppender("file_sonar"));
     assertThat(rootLogger.iteratorForAppenders()).toIterable().hasSize(2);
 
-    // verify no other logger writes to sonar.log
+    // verify no other logger except startup logger writes to sonar.log
     ctx.getLoggerList()
       .stream()
-      .filter(logger -> !ROOT_LOGGER_NAME.equals(logger.getName()))
+      .filter(logger -> !ROOT_LOGGER_NAME.equals(logger.getName()) && !LOGGER_STARTUP.equals(logger.getName()))
       .forEach(AppLoggingTest::verifyNoFileAppender);
   }
 
@@ -146,7 +147,7 @@ public class AppLoggingTest {
 
     ctx.getLoggerList()
       .stream()
-      .filter(logger -> !ROOT_LOGGER_NAME.equals(logger.getName()))
+      .filter(logger -> !ROOT_LOGGER_NAME.equals(logger.getName()) && !LOGGER_STARTUP.equals(logger.getName()))
       .forEach(AppLoggingTest::verifyNoFileAppender);
   }
 
diff --git a/server/sonar-main/src/test/java/org/sonar/application/process/StreamGobblerTest.java b/server/sonar-main/src/test/java/org/sonar/application/process/StreamGobblerTest.java
index 4be5cfc1cda..4d9be58da62 100644
--- a/server/sonar-main/src/test/java/org/sonar/application/process/StreamGobblerTest.java
+++ b/server/sonar-main/src/test/java/org/sonar/application/process/StreamGobblerTest.java
@@ -20,24 +20,40 @@
 package org.sonar.application.process;
 
 import java.io.InputStream;
+import java.nio.charset.StandardCharsets;
 import org.apache.commons.io.IOUtils;
+import org.junit.Before;
 import org.junit.Test;
 import org.slf4j.Logger;
+import org.sonar.application.config.AppSettings;
+import org.sonar.process.Props;
 
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.verifyNoInteractions;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
-import static org.mockito.Mockito.verifyZeroInteractions;
+import static org.mockito.Mockito.when;
+import static org.sonar.process.ProcessProperties.Property.LOG_JSON_OUTPUT;
 
 public class StreamGobblerTest {
 
+  private AppSettings appSettings = mock(AppSettings.class);
+  private Props props = mock(Props.class);
+
+  @Before
+  public void before() {
+    when(props.valueAsBoolean(LOG_JSON_OUTPUT.getKey(), false)).thenReturn(false);
+    when(appSettings.getProps()).thenReturn(props);
+  }
+
   @Test
   public void forward_stream_to_log() {
-    InputStream stream = IOUtils.toInputStream("one\nsecond log\nthird log\n");
+    InputStream stream = IOUtils.toInputStream("one\nsecond log\nthird log\n", StandardCharsets.UTF_8);
     Logger logger = mock(Logger.class);
+    Logger startupLogger = mock(Logger.class);
 
-    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", logger);
-    verifyZeroInteractions(logger);
+    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", appSettings, logger, startupLogger);
+    verifyNoInteractions(logger);
 
     gobbler.start();
     StreamGobbler.waitUntilFinish(gobbler);
@@ -46,5 +62,79 @@ public class StreamGobblerTest {
     verify(logger).info("second log");
     verify(logger).info("third log");
     verifyNoMoreInteractions(logger);
+    verifyNoInteractions(startupLogger);
+  }
+
+  @Test
+  public void startupLogIsLoggedWhenJSONFormatIsNotActive() {
+    InputStream stream = IOUtils.toInputStream("[startup] Admin is still using default credentials\nsecond log\n",
+      StandardCharsets.UTF_8);
+    Logger startupLogger = mock(Logger.class);
+    Logger logger = mock(Logger.class);
+
+    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", appSettings, logger, startupLogger);
+    verifyNoInteractions(startupLogger);
+
+    gobbler.start();
+    StreamGobbler.waitUntilFinish(gobbler);
+
+    verify(startupLogger).warn("Admin is still using default credentials");
+    verifyNoMoreInteractions(startupLogger);
+  }
+
+  /*
+   * This is scenario for known limitation of our approach when we detect more than we should - logs here are not really coming
+   * from a startup log from subprocess but from some other log but the message contains '[startup]'
+   */
+  @Test
+  public void startupLogIsLoggedWhenJSONFormatNotActiveAndMatchingStringIsIntMiddleOfTheTest() {
+    InputStream stream = IOUtils.toInputStream("Some other not [startup] log\nsecond log\n",
+      StandardCharsets.UTF_8);
+    Logger startupLogger = mock(Logger.class);
+    Logger logger = mock(Logger.class);
+
+    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", appSettings, logger, startupLogger);
+    verifyNoInteractions(startupLogger);
+
+    gobbler.start();
+    StreamGobbler.waitUntilFinish(gobbler);
+
+    verify(startupLogger).warn("log");
+    verifyNoMoreInteractions(startupLogger);
+  }
+
+  @Test
+  public void startupLogIsLoggedWhenJSONFormatIsActive() {
+    when(props.valueAsBoolean(LOG_JSON_OUTPUT.getKey(), false)).thenReturn(true);
+    InputStream stream = IOUtils.toInputStream("{ \"logger\": \"startup\", \"message\": \"Admin is still using default credentials\"}\n",
+      StandardCharsets.UTF_8);
+    Logger startupLogger = mock(Logger.class);
+    Logger logger = mock(Logger.class);
+
+    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", appSettings, logger, startupLogger);
+    verifyNoInteractions(startupLogger);
+
+    gobbler.start();
+    StreamGobbler.waitUntilFinish(gobbler);
+
+    verify(startupLogger).warn("Admin is still using default credentials");
+    verifyNoMoreInteractions(startupLogger);
+  }
+
+  @Test
+  public void startupLogIsNotLoggedWhenJSONFormatIsActiveAndLogHasWrongName() {
+    when(props.valueAsBoolean(LOG_JSON_OUTPUT.getKey(), false)).thenReturn(true);
+    InputStream stream = IOUtils.toInputStream("{ \"logger\": \"wrong-logger\", \"message\": \"Admin 'startup' is still using default credentials\"}\n",
+      StandardCharsets.UTF_8);
+    Logger startupLogger = mock(Logger.class);
+    Logger logger = mock(Logger.class);
+
+    StreamGobbler gobbler = new StreamGobbler(stream, "WEB", appSettings, logger, startupLogger);
+    verifyNoInteractions(startupLogger);
+
+    gobbler.start();
+    StreamGobbler.waitUntilFinish(gobbler);
+
+    verifyNoMoreInteractions(startupLogger);
   }
 }