diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index c0b79066e9b..6c73e8f1a4c 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/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 = @@ -1147,8 +1151,14 @@ 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); + setSystemPropertyDefault(SIMPLE_LOGGER_JSON_ENABLED_PROPERTY, "false"); + if (System.getProperty(SIMPLE_LOGGER_JSON_ENABLED_PROPERTY).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); + } String logLevel; if (isDebugMode()) { diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Constants.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Constants.java index 96be734ba22..c017f331181 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Constants.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Constants.java @@ -15,6 +15,7 @@ public final class Constants { */ public static final String[] BOOTSTRAP_PACKAGE_PREFIXES = { "datadog.slf4j", + "datadog.json", "datadog.context", "datadog.appsec.api", "datadog.trace.api", diff --git a/dd-java-agent/agent-logging/build.gradle b/dd-java-agent/agent-logging/build.gradle index 411e3573702..f4430f347ff 100644 --- a/dd-java-agent/agent-logging/build.gradle +++ b/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') + implementation project(':components:json') } diff --git a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatHelper.java b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatHelper.java index 463c5f42f76..f8218b78820 100644 --- a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatHelper.java +++ b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatHelper.java @@ -1,5 +1,6 @@ package datadog.trace.logging.simplelogger; +import datadog.json.JsonWriter; import datadog.trace.logging.LogLevel; import datadog.trace.logging.LoggerHelper; import org.slf4j.Marker; @@ -34,7 +35,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 +93,109 @@ 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('.'); + 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) { + writer.name("stackTrace"); + writer.beginArray(); for (StackTraceElement element : t.getStackTrace()) { - buf.append(" at "); - buf.append(element.toString()); + writer.value(element.toString()); } - buf.append(']'); + writer.endArray(); } + writer.endObject(); } } diff --git a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java b/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java index 955943fd6e9..6b75feb134d 100644 --- a/dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatSettings.java +++ b/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 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( diff --git a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/ddlogger/DDLoggerTest.groovy b/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/ddlogger/DDLoggerTest.groovy index 19bfe6c720f..d8d299439e4 100644 --- a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/ddlogger/DDLoggerTest.groovy +++ b/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, diff --git a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatHelperTest.groovy b/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatHelperTest.groovy index 2508aa62b4c..31084ee6494 100644 --- a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatHelperTest.groovy +++ b/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$/ } } diff --git a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatSettingsTest.groovy b/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatSettingsTest.groovy index cea1b88a6dd..80669b06463 100644 --- a/dd-java-agent/agent-logging/src/test/groovy/datadog/trace/logging/simplelogger/SLCompatSettingsTest.groovy +++ b/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"() { diff --git a/dd-java-agent/agent-logging/src/test/resources/slcompatsettingstest.properties b/dd-java-agent/agent-logging/src/test/resources/slcompatsettingstest.properties index 187f2eb8ae3..9ac2e8e3bd6 100644 --- a/dd-java-agent/agent-logging/src/test/resources/slcompatsettingstest.properties +++ b/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 diff --git a/dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/SpockRunner.java b/dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/SpockRunner.java index 55abe5d5efa..684b5c4b11a 100644 --- a/dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/SpockRunner.java +++ b/dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/SpockRunner.java @@ -38,6 +38,7 @@ public class SpockRunner extends JUnitPlatform { */ public static final String[] BOOTSTRAP_PACKAGE_PREFIXES_COPY = { "datadog.slf4j", + "datadog.json", "datadog.context", "datadog.appsec.api", "datadog.trace.api",