SC-702 support new property sonar.log.useJsonOutput

6 files changed, 329 insertions, 2 deletions

diff --git a/server/sonar-process/build.gradle b/server/sonar-process/build.gradle
index ee525939cb9..48e763545b2 100644
--- a/server/sonar-process/build.gradle
+++ b/server/sonar-process/build.gradle
@@ -11,6 +11,7 @@ dependencies {
   compile 'commons-codec:commons-codec'
   compile 'commons-io:commons-io'
   compile 'commons-lang:commons-lang'
+  compile 'com.google.code.gson:gson'
   compile 'com.google.guava:guava'
   compile 'com.hazelcast:hazelcast'
   compile 'org.slf4j:jul-to-slf4j'
diff --git a/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackHelper.java b/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackHelper.java
index 3af237048df..e1810fd3ffa 100644
--- a/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackHelper.java
+++ b/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackHelper.java
@@ -22,6 +22,7 @@ package org.sonar.process.logging;
 import ch.qos.logback.classic.Level;
 import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
 import ch.qos.logback.classic.joran.JoranConfigurator;
 import ch.qos.logback.classic.jul.LevelChangePropagator;
 import ch.qos.logback.classic.spi.ILoggingEvent;
@@ -30,6 +31,7 @@ import ch.qos.logback.core.ConsoleAppender;
 import ch.qos.logback.core.Context;
 import ch.qos.logback.core.FileAppender;
 import ch.qos.logback.core.encoder.Encoder;
+import ch.qos.logback.core.encoder.LayoutWrappingEncoder;
 import ch.qos.logback.core.joran.spi.JoranException;
 import ch.qos.logback.core.rolling.FixedWindowRollingPolicy;
 import ch.qos.logback.core.rolling.RollingFileAppender;
@@ -223,6 +225,21 @@ public class LogbackHelper extends AbstractLogHelper {
     configurator.doConfigure(LogbackHelper.class.getResource(xmlResourcePath));
   }
 
+  public Encoder<ILoggingEvent> createEncoder(Props props, RootLoggerConfig config, LoggerContext context) {
+    if (props.valueAsBoolean("sonar.log.useJsonOutput", false)) {
+      LayoutWrappingEncoder encoder = new LayoutWrappingEncoder<>();
+      encoder.setLayout(new LogbackJsonLayout(config.getProcessId().getKey()));
+      encoder.setContext(context);
+      encoder.start();
+      return encoder;
+    }
+    PatternLayoutEncoder encoder = new PatternLayoutEncoder();
+    encoder.setContext(context);
+    encoder.setPattern(buildLogPattern(config));
+    encoder.start();
+    return encoder;
+  }
+
   public RollingPolicy createRollingPolicy(Context ctx, Props props, String filenamePrefix) {
     String rollingPolicy = props.value(ROLLING_POLICY_PROPERTY, "time:yyyy-MM-dd");
     int maxFiles = props.valueAsInt(MAX_FILES_PROPERTY, 7);
diff --git a/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackJsonLayout.java b/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackJsonLayout.java
new file mode 100644
index 00000000000..94459687d0c
--- /dev/null
+++ b/server/sonar-process/src/main/java/org/sonar/process/logging/LogbackJsonLayout.java
@@ -0,0 +1,130 @@
+/*
+ * SonarQube
+ * Copyright (C) 2009-2019 SonarSource SA
+ * mailto:info AT sonarsource DOT com
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.process.logging;
+
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.spi.IThrowableProxy;
+import ch.qos.logback.classic.spi.StackTraceElementProxy;
+import ch.qos.logback.core.CoreConstants;
+import ch.qos.logback.core.LayoutBase;
+import com.google.gson.stream.JsonWriter;
+import java.io.IOException;
+import java.io.StringWriter;
+import java.time.Instant;
+import java.time.ZoneId;
+import java.time.format.DateTimeFormatter;
+import java.util.Locale;
+import java.util.Map;
+import java.util.regex.Pattern;
+import org.apache.commons.lang.StringUtils;
+
+import static java.lang.String.format;
+import static java.util.Objects.requireNonNull;
+
+/**
+ * Formats logs in JSON.
+ * <p>
+ * Strongly inspired by https://github.com/qos-ch/logback/blob/master/logback-classic/src/main/java/ch/qos/logback/classic/html/DefaultThrowableRenderer.java
+ */
+public class LogbackJsonLayout extends LayoutBase<ILoggingEvent> {
+
+  private static final DateTimeFormatter DATE_FORMATTER = DateTimeFormatter.ISO_OFFSET_DATE_TIME
+    .withLocale(Locale.US)
+    .withZone(ZoneId.systemDefault());
+  private static final Pattern NEWLINE_REGEXP = Pattern.compile("\n");
+
+  private final String processKey;
+
+  public LogbackJsonLayout(String processKey) {
+    this.processKey = requireNonNull(processKey);
+  }
+
+  String getProcessKey() {
+    return processKey;
+  }
+
+  @Override
+  public String doLayout(ILoggingEvent event) {
+    StringWriter output = new StringWriter();
+    try (JsonWriter json = new JsonWriter(output)) {
+      json.beginObject();
+      json.name("process").value(processKey);
+      for (Map.Entry<String, String> entry : event.getMDCPropertyMap().entrySet()) {
+        if (entry.getValue() != null) {
+          json.name(entry.getKey()).value(entry.getValue());
+        }
+      }
+      json
+        .name("instant").value(event.getTimeStamp())
+        .name("date").value(DATE_FORMATTER.format(Instant.ofEpochMilli(event.getTimeStamp())))
+        .name("severity").value(event.getLevel().toString())
+        .name("logger").value(event.getLoggerName())
+        .name("message").value(NEWLINE_REGEXP.matcher(event.getFormattedMessage()).replaceAll("\r"));
+      IThrowableProxy tp = event.getThrowableProxy();
+      if (tp != null) {
+        json.name("stacktrace").beginArray();
+        int nbOfTabs = 0;
+        while (tp != null) {
+          printFirstLine(json, tp, nbOfTabs);
+          render(json, tp, nbOfTabs);
+          tp = tp.getCause();
+          nbOfTabs++;
+        }
+        json.endArray();
+
+      }
+      json.endObject();
+    } catch (Exception e) {
+      e.printStackTrace();
+      throw new IllegalStateException("BUG - fail to create JSON", e);
+    }
+    output.write(System.lineSeparator());
+    return output.toString();
+  }
+
+  private static void render(JsonWriter output, IThrowableProxy tp, int nbOfTabs) throws IOException {
+    String tabs = StringUtils.repeat("\t", nbOfTabs);
+    int commonFrames = tp.getCommonFrames();
+    StackTraceElementProxy[] stepArray = tp.getStackTraceElementProxyArray();
+
+    for (int i = 0; i < stepArray.length - commonFrames; i++) {
+      StackTraceElementProxy step = stepArray[i];
+      output.value(tabs + step.toString());
+    }
+
+    if (commonFrames > 0) {
+      output.value(tabs + "... " + commonFrames + " common frames omitted");
+    }
+
+    for (IThrowableProxy suppressed : tp.getSuppressed()) {
+      output.value(format("%sSuppressed: %s: %s", tabs, suppressed.getClassName(), suppressed.getMessage()));
+      render(output, suppressed, nbOfTabs + 1);
+    }
+  }
+
+  private static void printFirstLine(JsonWriter output, IThrowableProxy tp, int nbOfTabs) throws IOException {
+    String tabs = StringUtils.repeat("\t", nbOfTabs);
+    int commonFrames = tp.getCommonFrames();
+    if (commonFrames > 0) {
+      output.value(tabs + CoreConstants.CAUSED_BY);
+    }
+    output.value(tabs + tp.getClassName() + ": " + tp.getMessage());
+  }
+}
diff --git a/server/sonar-process/src/main/java/org/sonar/process/logging/RootLoggerConfig.java b/server/sonar-process/src/main/java/org/sonar/process/logging/RootLoggerConfig.java
index d9960ce93cf..2c503252530 100644
--- a/server/sonar-process/src/main/java/org/sonar/process/logging/RootLoggerConfig.java
+++ b/server/sonar-process/src/main/java/org/sonar/process/logging/RootLoggerConfig.java
@@ -37,11 +37,11 @@ public final class RootLoggerConfig {
     return new Builder();
   }
 
-  ProcessId getProcessId() {
+  public ProcessId getProcessId() {
     return processId;
   }
 
-  String getThreadIdFieldPattern() {
+  public String getThreadIdFieldPattern() {
     return threadIdFieldPattern;
   }
 
diff --git a/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackHelperTest.java b/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackHelperTest.java
index 4d07ae721ea..924e45bec0c 100644
--- a/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackHelperTest.java
+++ b/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackHelperTest.java
@@ -28,6 +28,9 @@ import ch.qos.logback.core.Appender;
 import ch.qos.logback.core.AppenderBase;
 import ch.qos.logback.core.ConsoleAppender;
 import ch.qos.logback.core.FileAppender;
+import ch.qos.logback.core.Layout;
+import ch.qos.logback.core.encoder.Encoder;
+import ch.qos.logback.core.encoder.LayoutWrappingEncoder;
 import ch.qos.logback.core.rolling.FixedWindowRollingPolicy;
 import ch.qos.logback.core.rolling.RollingFileAppender;
 import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy;
@@ -476,6 +479,32 @@ public class LogbackHelperTest {
     assertThat(context.getLogger("fii").getLevel()).isNull();
   }
 
+  @Test
+  public void createEncoder_uses_pattern_by_default() {
+    RootLoggerConfig config = newRootLoggerConfigBuilder()
+      .setProcessId(ProcessId.WEB_SERVER)
+      .build();
+
+    Encoder<ILoggingEvent> encoder = underTest.createEncoder(props, config, underTest.getRootContext());
+
+    assertThat(encoder).isInstanceOf(PatternLayoutEncoder.class);
+  }
+
+  @Test
+  public void createEncoder_uses_json_output() {
+    props.set("sonar.log.useJsonOutput", "true");
+    RootLoggerConfig config = newRootLoggerConfigBuilder()
+      .setProcessId(ProcessId.WEB_SERVER)
+      .build();
+
+    Encoder<ILoggingEvent> encoder = underTest.createEncoder(props, config, underTest.getRootContext());
+
+    assertThat(encoder).isInstanceOf(LayoutWrappingEncoder.class);
+    Layout layout = ((LayoutWrappingEncoder) encoder).getLayout();
+    assertThat(layout).isInstanceOf(LogbackJsonLayout.class);
+    assertThat(((LogbackJsonLayout)layout).getProcessKey()).isEqualTo("web");
+  }
+
   private LogLevelConfig.Builder newLogLevelConfig() {
     return LogLevelConfig.newBuilder(ROOT_LOGGER_NAME);
   }
diff --git a/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackJsonLayoutTest.java b/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackJsonLayoutTest.java
new file mode 100644
index 00000000000..9c7254e5c6c
--- /dev/null
+++ b/server/sonar-process/src/test/java/org/sonar/process/logging/LogbackJsonLayoutTest.java
@@ -0,0 +1,150 @@
+/*
+ * SonarQube
+ * Copyright (C) 2009-2019 SonarSource SA
+ * mailto:info AT sonarsource DOT com
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+ */
+package org.sonar.process.logging;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.LoggingEvent;
+import com.google.gson.Gson;
+import java.time.Instant;
+import java.time.format.DateTimeFormatter;
+import org.assertj.core.data.Offset;
+import org.junit.Test;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class LogbackJsonLayoutTest {
+
+  private LogbackJsonLayout underTest = new LogbackJsonLayout("web");
+
+  @Test
+  public void test_simple_log() {
+    LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the message", null, new Object[0]);
+
+    String log = underTest.doLayout(event);
+
+    JsonLog json = new Gson().fromJson(log, JsonLog.class);
+    assertThat(json.process).isEqualTo("web");
+    assertThat(json.instant).isCloseTo(System.currentTimeMillis(), Offset.offset(10_000L));
+    assertThat(Instant.from(DateTimeFormatter.ISO_OFFSET_DATE_TIME.parse(json.date)).toEpochMilli()).isEqualTo(json.instant);
+    assertThat(json.severity).isEqualTo("WARN");
+    assertThat(json.logger).isEqualTo("the.logger");
+    assertThat(json.message).isEqualTo("the message");
+    assertThat(json.message).isEqualTo("the message");
+    assertThat(json.stacktrace).isNull();
+    assertThat(json.fromMdc).isNull();
+  }
+
+  @Test
+  public void test_log_with_throwable_and_no_cause() {
+    Throwable exception = new IllegalStateException("BOOM");
+    LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the message", exception, new Object[0]);
+
+    String log = underTest.doLayout(event);
+
+    JsonLog json = new Gson().fromJson(log, JsonLog.class);
+    assertThat(json.process).isEqualTo("web");
+    assertThat(json.instant).isCloseTo(System.currentTimeMillis(), Offset.offset(10_000L));
+    assertThat(Instant.from(DateTimeFormatter.ISO_OFFSET_DATE_TIME.parse(json.date)).toEpochMilli()).isEqualTo(json.instant);
+    assertThat(json.severity).isEqualTo("WARN");
+    assertThat(json.logger).isEqualTo("the.logger");
+    assertThat(json.message).isEqualTo("the message");
+    assertThat(json.stacktrace.length).isGreaterThan(5);
+    assertThat(json.stacktrace[0]).isEqualTo("java.lang.IllegalStateException: BOOM");
+    assertThat(json.stacktrace[1]).startsWith("at ").contains("LogbackJsonLayoutTest.test_log_with_throwable");
+    assertThat(json.fromMdc).isNull();
+  }
+
+  @Test
+  public void test_log_with_throwable_and_cause() {
+    Throwable rootCause = new IllegalArgumentException("Root cause");
+    Throwable exception = new IllegalStateException("BOOM", rootCause);
+    LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the message", exception, new Object[0]);
+
+    String log = underTest.doLayout(event);
+
+    JsonLog json = new Gson().fromJson(log, JsonLog.class);
+    assertThat(json.stacktrace.length).isGreaterThan(5);
+    assertThat(json.stacktrace[0]).isEqualTo("java.lang.IllegalStateException: BOOM");
+    assertThat(json.stacktrace[1]).startsWith("at org.sonar.process.logging.LogbackJsonLayoutTest.test_log_with_throwable_and_cause(LogbackJsonLayoutTest.java:");
+    assertThat(json.stacktrace)
+      .contains("\tCaused by: ")
+      .contains("\tjava.lang.IllegalArgumentException: Root cause");
+  }
+
+  @Test
+  public void test_log_with_suppressed_throwable() {
+    Exception exception = new Exception("BOOM");
+    exception.addSuppressed(new IllegalStateException("foo"));
+    LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the message", exception, new Object[0]);
+
+    String log = underTest.doLayout(event);
+
+    JsonLog json = new Gson().fromJson(log, JsonLog.class);
+    assertThat(json.stacktrace.length).isGreaterThan(5);
+    assertThat(json.stacktrace[0]).isEqualTo("java.lang.Exception: BOOM");
+    assertThat(json.stacktrace).contains("Suppressed: java.lang.IllegalStateException: foo");
+  }
+
+  @Test
+  public void test_log_with_message_arguments() {
+    LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the {}", null, new Object[]{"message"});
+
+    String log = underTest.doLayout(event);
+
+    JsonLog json = new Gson().fromJson(log, JsonLog.class);
+    assertThat(json.process).isEqualTo("web");
+    assertThat(json.instant).isCloseTo(System.currentTimeMillis(), Offset.offset(10_000L));
+    assertThat(Instant.from(DateTimeFormatter.ISO_OFFSET_DATE_TIME.parse(json.date)).toEpochMilli()).isEqualTo(json.instant);
+    assertThat(json.severity).isEqualTo("WARN");
+    assertThat(json.logger).isEqualTo("the.logger");
+    assertThat(json.message).isEqualTo("the message");
+    assertThat(json.stacktrace).isNull();
+    assertThat(json.fromMdc).isNull();
+  }
+
+  @Test
+  public void test_log_with_MDC() {
+    try {
+      LoggingEvent event = new LoggingEvent("org.foundation.Caller", (Logger) LoggerFactory.getLogger("the.logger"), Level.WARN, "the message", null, new Object[0]);
+      MDC.put("fromMdc", "foo");
+
+      String log = underTest.doLayout(event);
+
+      JsonLog json = new Gson().fromJson(log, JsonLog.class);
+      assertThat(json.fromMdc).isEqualTo("foo");
+    } finally {
+      MDC.clear();
+    }
+  }
+
+  private static class JsonLog {
+    private String process;
+    private long instant;
+    private String date;
+    private String severity;
+    private String logger;
+    private String message;
+    private String fromMdc;
+    private String[] stacktrace;
+  }
+}