Add the possibility to output the logs of the Java tracer in JSON

dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java

@@ -68,6 +68,10 @@ public class Agent {
 
   private static final String SIMPLE_LOGGER_SHOW_DATE_TIME_PROPERTY =
       "datadog.slf4j.simpleLogger.showDateTime";
+  private static final String SIMPLE_LOGGER_JSON_ENABLED_PROPERTY =
+      "datadog.slf4j.simpleLogger.jsonEnabled";
+  private static final String SIMPLE_LOGGER_DATE_TIME_FORMAT_JSON_DEFAULT =
+      "yyyy-MM-dd'T'HH:mm:ss.SSSZ";
   private static final String SIMPLE_LOGGER_DATE_TIME_FORMAT_PROPERTY =
       "datadog.slf4j.simpleLogger.dateTimeFormat";
   private static final String SIMPLE_LOGGER_DATE_TIME_FORMAT_DEFAULT =
@@ -1130,8 +1134,18 @@ private static synchronized void startDebuggerAgent(
 
   private static void configureLogger() {
     setSystemPropertyDefault(SIMPLE_LOGGER_SHOW_DATE_TIME_PROPERTY, "true");
-    setSystemPropertyDefault(
-        SIMPLE_LOGGER_DATE_TIME_FORMAT_PROPERTY, SIMPLE_LOGGER_DATE_TIME_FORMAT_DEFAULT);
+    String simpleLoggerJsonInSystemPropertySetByUser =
+        System.getProperty(SIMPLE_LOGGER_JSON_ENABLED_PROPERTY);
+
+    if ((simpleLoggerJsonInSystemPropertySetByUser != null
+        && simpleLoggerJsonInSystemPropertySetByUser.equalsIgnoreCase("true"))) {
+      setSystemPropertyDefault(
+          SIMPLE_LOGGER_DATE_TIME_FORMAT_PROPERTY, SIMPLE_LOGGER_DATE_TIME_FORMAT_JSON_DEFAULT);
+    } else {
+      setSystemPropertyDefault(
+          SIMPLE_LOGGER_DATE_TIME_FORMAT_PROPERTY, SIMPLE_LOGGER_DATE_TIME_FORMAT_DEFAULT);
+      setSystemPropertyDefault(SIMPLE_LOGGER_JSON_ENABLED_PROPERTY, "false");
+    }
 
     String logLevel;
     if (isDebugMode()) {

dd-java-agent/agent-logging/build.gradle

@@ -23,4 +23,5 @@ dependencies {
   // This is fine since this project is shadowed into the agent-jar by dd-java-agent:agent-bootstrap
   api libs.slf4j
   api project(':internal-api')
+  api project(':components:json')
 }

dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatHelper.java

@@ -1,7 +1,11 @@
 package datadog.trace.logging.simplelogger;
 
+import datadog.json.JsonWriter;
 import datadog.trace.logging.LogLevel;
 import datadog.trace.logging.LoggerHelper;
+import java.util.Arrays;
+import java.util.Iterator;
+import java.util.List;
 import org.slf4j.Marker;
 
 /**
@@ -34,7 +38,11 @@ public void log(LogLevel level, Marker marker, String message, Throwable t) {
     if (settings.showDateTime) {
       timeMillis = System.currentTimeMillis();
     }
-    log(level, marker, SLCompatFactory.START_TIME, timeMillis, message, t);
+    if (settings.jsonEnabled) {
+      logJson(level, marker, SLCompatFactory.START_TIME, timeMillis, message, t);
+    } else {
+      log(level, marker, SLCompatFactory.START_TIME, timeMillis, message, t);
+    }
   }
 
   void log(
@@ -88,32 +96,112 @@ void log(
     }
     buf.append(' ');
 
-    if (logName.length() > 0) {
+    if (!logName.isEmpty()) {
       buf.append(logName).append(" - ");
     }
 
     buf.append(message);
 
-    if (settings.embedException) {
+    if (settings.embedException && t != null) {
       embedException(buf, t);
     }
 
-    settings.printStream.println(buf.toString());
+    settings.printStream.println(buf);
     if (!settings.embedException && t != null) {
       t.printStackTrace(settings.printStream);
     }
   }
 
   private void embedException(StringBuilder buf, Throwable t) {
+    buf.append(" [exception:");
+    buf.append(t.toString());
+    buf.append(".");
+    for (StackTraceElement element : t.getStackTrace()) {
+      buf.append(" at ");
+      buf.append(element.toString());
+    }
+    buf.append("]");
+  }
+
+  void logJson(
+      LogLevel level,
+      Marker marker,
+      long startTimeMillis,
+      long timeMillis,
+      String message,
+      Throwable t) {
+    String threadName = null;
+    if (settings.showThreadName) {
+      threadName = Thread.currentThread().getName();
+    }
+    logJson(level, marker, startTimeMillis, timeMillis, threadName, message, t);
+  }
+
+  void logJson(
+      LogLevel level,
+      Marker marker,
+      long startTimeMillis,
+      long timeMillis,
+      String threadName,
+      String message,
+      Throwable t) {
+
+    JsonWriter writer = new JsonWriter();
+    writer.beginObject();
+    writer.name("origin").value("dd.trace");
+
+    if (timeMillis >= 0 && settings.showDateTime) {
+      writer.name("date");
+      StringBuilder buf = new StringBuilder(32);
+      settings.dateTimeFormatter.appendFormattedDate(buf, timeMillis, startTimeMillis);
+      writer.value(buf.toString());
+    }
+
+    if (settings.showThreadName && threadName != null) {
+      writer.name("logger.thread_name").value(threadName);
+    }
+
+    writer.name("level");
+
+    if (settings.warnLevelString != null && level == LogLevel.WARN) {
+      writer.value(wrappedValueWithBracketsIfRequested(settings.warnLevelString));
+    } else if (marker != null) {
+      writer.value(wrappedValueWithBracketsIfRequested(marker.getName()));
+    } else {
+      writer.value(wrappedValueWithBracketsIfRequested(level.name()));
+    }
+
+    if (!logName.isEmpty()) {
+      writer.name("logger.name").value(logName);
+    }
+    writer.name("message").value(message);
+
     if (t != null) {
-      buf.append(" [exception:");
-      buf.append(t.toString());
-      buf.append('.');
-      for (StackTraceElement element : t.getStackTrace()) {
-        buf.append(" at ");
-        buf.append(element.toString());
+      embedExceptionJson(writer, t);
+    }
+    writer.endObject();
+    settings.printStream.println(writer);
+  }
+
+  private String wrappedValueWithBracketsIfRequested(String value) {
+    return settings.levelInBrackets ? '[' + value + ']' : value;
+  }
+
+  private void embedExceptionJson(JsonWriter writer, Throwable t) {
+    writer.name("exception");
+    writer.beginObject();
+    writer.name("message").value(t.getMessage());
+    if (t.getStackTrace().length > 0) {
+      List<StackTraceElement> stackTraceElementList = Arrays.asList(t.getStackTrace());
+      Iterator<StackTraceElement> it = stackTraceElementList.iterator();
+      writer.name("stackTrace");
+      writer.beginArray();
+      while (it.hasNext()) {
+        StackTraceElement element = it.next();
+        writer.value(element.toString());
       }
-      buf.append(']');
+      writer.endArray();
+      writer.endObject();
     }
   }
 }

dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java

@@ -33,6 +33,7 @@ public static final class Names {
     public static final String SHOW_THREAD_NAME = "showThreadName";
     public static final String DATE_TIME_FORMAT = "dateTimeFormat";
     public static final String SHOW_DATE_TIME = "showDateTime";
+    public static final String JSON_ENABLED = "jsonEnabled";
     public static final String DEFAULT_LOG_LEVEL = "defaultLogLevel";
     public static final String EMBED_EXCEPTION = "embedException";
     public static final String CONFIGURATION_FILE = "configurationFile";
@@ -53,6 +54,7 @@ public static final class Keys {
     public static final String SHOW_THREAD_NAME = PREFIX + Names.SHOW_THREAD_NAME;
     public static final String DATE_TIME_FORMAT = PREFIX + Names.DATE_TIME_FORMAT;
     public static final String SHOW_DATE_TIME = PREFIX + Names.SHOW_DATE_TIME;
+    public static final String JSON_ENABLED = PREFIX + Names.JSON_ENABLED;
     public static final String DEFAULT_LOG_LEVEL = PREFIX + Names.DEFAULT_LOG_LEVEL;
     public static final String EMBED_EXCEPTION = PREFIX + Names.EMBED_EXCEPTION;
 
@@ -70,6 +72,7 @@ public static final class Defaults {
     public static final boolean SHOW_THREAD_NAME = true;
     public static final String DATE_TIME_FORMAT = null;
     public static final boolean SHOW_DATE_TIME = false;
+    public static final boolean JSON_ENABLED = false;
     public static final String DEFAULT_LOG_LEVEL = "INFO";
     public static final boolean EMBED_EXCEPTION = false;
 
@@ -271,6 +274,7 @@ static boolean getBoolean(
   final boolean showThreadName;
   final DTFormatter dateTimeFormatter;
   final boolean showDateTime;
+  final boolean jsonEnabled;
   final LogLevel defaultLogLevel;
   final boolean embedException;
 
@@ -304,6 +308,7 @@ public SLCompatSettings(
             getString(
                 properties, fileProperties, Keys.DATE_TIME_FORMAT, Defaults.DATE_TIME_FORMAT)),
         getBoolean(properties, fileProperties, Keys.SHOW_DATE_TIME, Defaults.SHOW_DATE_TIME),
+        getBoolean(properties, fileProperties, Keys.JSON_ENABLED, Defaults.JSON_ENABLED),
         LogLevel.fromString(
             getString(
                 properties, fileProperties, Keys.DEFAULT_LOG_LEVEL, Defaults.DEFAULT_LOG_LEVEL)),
@@ -321,6 +326,7 @@ public SLCompatSettings(
       boolean showThreadName,
       DTFormatter dateTimeFormatter,
       boolean showDateTime,
+      boolean jsonEnabled,
       LogLevel defaultLogLevel,
       boolean embedException) {
     this.properties = properties;
@@ -333,6 +339,7 @@ public SLCompatSettings(
     this.showThreadName = showThreadName;
     this.dateTimeFormatter = dateTimeFormatter;
     this.showDateTime = showDateTime;
+    this.jsonEnabled = jsonEnabled;
     this.defaultLogLevel = defaultLogLevel;
     this.embedException = embedException;
   }
@@ -375,6 +382,7 @@ public Map<String, Object> getSettingsDescription() {
     settingsDescription.put(Names.SHOW_SHORT_LOG_NAME, showShortLogName);
     settingsDescription.put(Names.SHOW_THREAD_NAME, showThreadName);
     settingsDescription.put(Names.SHOW_DATE_TIME, showDateTime);
+    settingsDescription.put(Names.JSON_ENABLED, jsonEnabled);
     String dateTimeFormat =
         getString(properties, fileProperties, Keys.DATE_TIME_FORMAT, Defaults.DATE_TIME_FORMAT);
     settingsDescription.put(

dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/ddlogger/DDLoggerTest.groovy

@@ -359,6 +359,7 @@ class DDLoggerTest extends LogValidatingSpecification {
       (Names.SHOW_SHORT_LOG_NAME): Defaults.SHOW_SHORT_LOG_NAME,
       (Names.SHOW_THREAD_NAME): false,
       (Names.SHOW_DATE_TIME): true,
+      (Names.JSON_ENABLED): Defaults.JSON_ENABLED,
       (Names.DATE_TIME_FORMAT): "relative",
       (Names.DEFAULT_LOG_LEVEL): expectedLevel,
       (Names.EMBED_EXCEPTION): Defaults.EMBED_EXCEPTION,

dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatHelperTest.groovy

@@ -139,25 +139,94 @@ class SLCompatHelperTest extends Specification {
     def printStream = new PrintStream(outputStream, true)
     def props = new Properties()
     def dateTimeFormatter = SLCompatSettings.DTFormatter.create(dateTFS)
-    def settings = new SLCompatSettings(props, props, warnS, showB, printStream, showS, showL, showT, dateTimeFormatter, showDT, LogLevel.INFO, false)
+    def settings = new SLCompatSettings(props, props, warnS, showB, printStream, showS, showL, showT, dateTimeFormatter, showDT, jsonE, LogLevel.INFO, false)
     def helper = new SLCompatHelper("foo.bar", settings)
+
     helper.log(level, null, 0, 4711, "thread", "log", null)
 
     then:
     outputStream.toString() == expected
 
     where:
-    level         | warnS    | showB | showS | showL | showT | dateTFS                 | showDT | expected
-    LogLevel.WARN | null     | false | false | false | false | null                    | false  | "WARN log\n"
-    LogLevel.WARN | "DANGER" | false | false | false | false | null                    | false  | "DANGER log\n"
-    LogLevel.INFO | "DANGER" | false | false | false | false | null                    | false  | "INFO log\n"
-    LogLevel.WARN | null     | true  | false | false | false | null                    | false  | "[WARN] log\n"
-    LogLevel.INFO | null     | false | true  | false | false | null                    | false  | "INFO bar - log\n"
-    LogLevel.INFO | null     | true  | true  | true  | false | null                    | false  | "[INFO] bar - log\n"
-    LogLevel.INFO | null     | true  | false | true  | false | null                    | false  | "[INFO] foo.bar - log\n"
-    LogLevel.INFO | null     | false | false | false | true  | null                    | false  | "[thread] INFO log\n"
-    LogLevel.INFO | null     | false | false | false | true  | null                    | true   | "4711 [thread] INFO log\n"
-    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | false  | "[thread] INFO log\n"
-    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | true   | "${new SimpleDateFormat("yyyy-MM-dd HH:mm:ss z").format(new Date(4711))} [thread] INFO log\n"
+    level         | warnS    | showB | showS | showL | showT | dateTFS                 | showDT |  jsonE | expected
+    LogLevel.WARN | null     | false | false | false | false | null                    | false  |  false | "WARN log\n"
+    LogLevel.WARN | "DANGER" | false | false | false | false | null                    | false  |  false | "DANGER log\n"
+    LogLevel.INFO | "DANGER" | false | false | false | false | null                    | false  |  false | "INFO log\n"
+    LogLevel.WARN | null     | true  | false | false | false | null                    | false  |  false | "[WARN] log\n"
+    LogLevel.INFO | null     | false | true  | false | false | null                    | false  |  false | "INFO bar - log\n"
+    LogLevel.INFO | null     | true  | true  | true  | false | null                    | false  |  false | "[INFO] bar - log\n"
+    LogLevel.INFO | null     | true  | false | true  | false | null                    | false  |  false | "[INFO] foo.bar - log\n"
+    LogLevel.INFO | null     | false | false | false | true  | null                    | false  |  false | "[thread] INFO log\n"
+    LogLevel.INFO | null     | false | false | false | true  | null                    | true   |  false | "4711 [thread] INFO log\n"
+    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | false  |  false | "[thread] INFO log\n"
+    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | true   |  false | "${new SimpleDateFormat("yyyy-MM-dd HH:mm:ss z").format(new Date(4711))} [thread] INFO log\n"
+  }
+
+
+
+  def "test log output with Json configuration key"() {
+    when:
+    def outputStream = new ByteArrayOutputStream()
+    def printStream = new PrintStream(outputStream, true)
+    def props = new Properties()
+    def dateTimeFormatter = SLCompatSettings.DTFormatter.create(dateTFS)
+    def settings = new SLCompatSettings(props, props, warnS, showB, printStream, showS, showL, showT, dateTimeFormatter, showDT, jsonE, LogLevel.INFO, false)
+    def helper = new SLCompatHelper("foo.bar", settings)
+
+    // helper.log is where we split between logs and JSON logs
+    helper.log(level, null, "log", null)
+
+    then:
+    outputStream.toString() == expected
+
+    where:
+    level         | warnS    | showB | showS | showL | showT | dateTFS                 | showDT |  jsonE | expected
+    LogLevel.WARN | null     | false | false | false | false | null                    | false  |  false | "WARN log\n"
+    LogLevel.WARN | "DANGER" | false | false | false | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"DANGER\",\"message\":\"log\"}\n"
+  }
+
+  def "test log output in Json"() {
+    when:
+    def outputStream = new ByteArrayOutputStream()
+    def printStream = new PrintStream(outputStream, true)
+    def props = new Properties()
+    def dateTimeFormatter = SLCompatSettings.DTFormatter.create(dateTFS)
+    def settings = new SLCompatSettings(props, props, warnS, showB, printStream, showS, showL, showT, dateTimeFormatter, showDT, jsonE, LogLevel.INFO, false)
+    def helper = new SLCompatHelper("foo.bar", settings)
+
+    helper.logJson(level,null,0,4711,"thread","log", null)
+
+    then:
+    outputStream.toString() == expected
+
+    where:
+    level         | warnS    | showB | showS | showL | showT | dateTFS                 | showDT |  jsonE | expected
+    LogLevel.WARN | "DANGER" | false | false | false | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"DANGER\",\"message\":\"log\"}\n"
+    LogLevel.INFO | "DANGER" | false | false | false | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"INFO\",\"message\":\"log\"}\n"
+    LogLevel.WARN | null     | true  | false | false | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"[WARN]\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | false | true  | false | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"INFO\",\"logger.name\":\"bar\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | true  | true  | true  | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"[INFO]\",\"logger.name\":\"bar\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | true  | false | true  | false | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"level\":\"[INFO]\",\"logger.name\":\"foo.bar\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | false | false | false | true  | null                    | false  |  true  | "{\"origin\":\"dd.trace\",\"logger.thread_name\":\"thread\",\"level\":\"INFO\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | false  |  true  | "{\"origin\":\"dd.trace\",\"logger.thread_name\":\"thread\",\"level\":\"INFO\",\"message\":\"log\"}\n"
+    LogLevel.INFO | null     | false | false | false | true  | "yyyy-MM-dd HH:mm:ss z" | true   |  true  | "{\"origin\":\"dd.trace\",\"date\":\"${new SimpleDateFormat(dateTFS).format(new Date(4711))}\",\"logger.thread_name\":\"thread\",\"level\":\"INFO\",\"message\":\"log\"}\n"
+  }
+
+
+  def "test logging with an embedded exception in Json"() {
+    setup:
+    def outputStream = new ByteArrayOutputStream()
+    def printStream = new PrintStream(outputStream, true)
+    def props = new Properties()
+    def dateTimeFormatter = SLCompatSettings.DTFormatter.create("yyyy-MM-dd HH:mm:ss z")
+    def settings = new SLCompatSettings(props, props, null, false, printStream, false,true,false, dateTimeFormatter, false, true, LogLevel.INFO, true)
+    def helper = new SLCompatHelper("foo", settings)
+    try {
+      throw new IOException("wrong")
+    } catch(Exception exception) {
+      helper.log(LogLevel.INFO, null, "log", exception)
+    }
+    expect:
+    outputStream.toString() ==~ /^\{"origin":"dd.trace","level":"INFO","logger.name":"foo","message":"log","exception":\{"message":"wrong","stackTrace":\[.*\]\}\}\n$/
   }
 }

dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatSettingsTest.groovy

@@ -71,6 +71,7 @@ class SLCompatSettingsTest extends Specification {
     settings.dateTimeFormatter.class == SLCompatSettings.DiffDTFormatter
     settings.showDateTime == false
     settings.defaultLogLevel == LogLevel.INFO
+    settings.jsonEnabled == false
   }
 
   def "test file properties"() {
@@ -91,6 +92,7 @@ class SLCompatSettingsTest extends Specification {
     formatted.toString() == new SimpleDateFormat("'['yy-dd-MM HH:mm:ss:SSS Z']'").format(new Date(4711 << 20))
     settings.showDateTime == true
     settings.defaultLogLevel == LogLevel.DEBUG
+    settings.jsonEnabled == true
   }
 
   def "test log file creation"() {

dd-java-agent/agent-logging/src/test/resources/slcompatsettingstest.properties

@@ -7,3 +7,4 @@ datadog.slf4j.simpleLogger.showThreadName = false
 datadog.slf4j.simpleLogger.dateTimeFormat = '['yy-dd-MM HH:mm:ss:SSS Z']'
 datadog.slf4j.simpleLogger.showDateTime = true
 datadog.slf4j.simpleLogger.defaultLogLevel = DEBUG
+datadog.slf4j.simpleLogger.jsonEnabled = true