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;
* 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));
}
/**
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},
.setWatcherDelayMs(processWatcherDelayMs)
.setStopTimeout(stopTimeoutFor(processId, settings))
.setHardStopTimeout(HARD_STOP_TIMEOUT)
+ .setAppSettings(settings)
.build();
processesById.put(process.getProcessId(), process);
}
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;
private final Timeout stopTimeout;
private final Timeout hardStopTimeout;
private final long watcherDelayMs;
+ private final AppSettings appSettings;
private ManagedProcess process;
private StreamGobbler stdOutGobbler;
this.watcherDelayMs = builder.watcherDelayMs;
this.stopWatcher = new StopWatcher();
this.eventWatcher = new EventWatcher();
+ this.appSettings = builder.settings;
}
public boolean start(Supplier<ManagedProcess> commandLauncher) {
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();
private long watcherDelayMs = DEFAULT_WATCHER_DELAY_MS;
private Timeout stopTimeout;
private Timeout hardStopTimeout;
+ private AppSettings settings;
private Builder(ProcessId processId) {
this.processId = processId;
ensureHardStopTimeoutNonNull(this.hardStopTimeout);
return new ManagedProcessHandler(this);
}
+
+ public Builder setAppSettings(AppSettings settings) {
+ this.settings = settings;
+ return this;
+ }
}
public static final class Timeout {
*/
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
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 {
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;
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);
}
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);
}
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);
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);
}
}
projects / sonarqube.git / commitdiff