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

2 files changed, 98 insertions, 7 deletions

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);
   }
 }