Closes #465 - Ability to automatically inject trace ids into log mess…

…ages for log4j version 1 (#464)

inspectit-ocelot-agent/build.gradle

@@ -184,7 +184,7 @@ task systemTest {
             doFirst {
                 jvmArgs "-Dinspectit.config.file-based.path=$projectDir/src/system-test/resources/config"  // make inspectIT scan the workdir for configs
                 jvmArgs "-Dinspectit.publishOpenCensusToBootstrap=true"  // make inspectIT push OC to the bootstrap
-                jvmArgs jacoco.asJvmArg + ",inclbootstrapclasses=true"  // JaCoCo agent first + bootstrap instrumentaiton
+                jvmArgs jacoco.asJvmArg + ",inclbootstrapclasses=true"  // JaCoCo agent first + bootstrap instrumentation
                 jvmArgs "-javaagent:${agentJarPath}"  // Our agent second.
                 jacoco.enabled = false  // Don't add the JaCoCo agent again.
             }

inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/special/logging/Log4J2TraceIdAutoInjectorTest.java

@@ -0,0 +1,111 @@
+package rocks.inspectit.ocelot.instrumentation.special.logging;
+
+import io.opencensus.common.Scope;
+import io.opencensus.trace.Tracing;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.junit.jupiter.api.Test;
+import rocks.inspectit.ocelot.instrumentation.InstrumentationSysTestBase;
+import rocks.inspectit.ocelot.logging.Log4J2LoggingRecorder;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class Log4J2TraceIdAutoInjectorTest extends InstrumentationSysTestBase {
+
+    private static final Logger LOGGER = LogManager.getLogger(Log4J2TraceIdAutoInjectorTest.class);
+
+    @Test
+    public void logStringAndTraceExists() {
+        Log4J2LoggingRecorder.loggingEvents.clear();
+        String message = "This is a traced String in {}.";
+        String traceId;
+
+        try (Scope scope = Tracing.getTracer().spanBuilder("test").startScopedSpan()) {
+            traceId = Tracing.getTracer().getCurrentSpan().getContext().getTraceId().toLowerBase16();
+
+            LOGGER.info(message, "Log4J2");
+        }
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents.get(0))
+                .extracting(event -> event.getMessage().getFormattedMessage())
+                .isEqualTo("[TraceID: " + traceId + "] This is a traced String in Log4J2.");
+    }
+
+    @Test
+    public void logCharSequenceAndTraceExists() {
+        Log4J2LoggingRecorder.loggingEvents.clear();
+        CharSequence message = "This is a traced CharSequence in Log4J2.";
+        String traceId;
+
+        try (Scope scope = Tracing.getTracer().spanBuilder("test").startScopedSpan()) {
+            traceId = Tracing.getTracer().getCurrentSpan().getContext().getTraceId().toLowerBase16();
+
+            LOGGER.info(message);
+        }
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents.get(0))
+                .extracting(event -> event.getMessage().getFormattedMessage())
+                .isEqualTo("[TraceID: " + traceId + "] This is a traced CharSequence in Log4J2.");
+    }
+
+    @Test
+    public void logObjectAndTraceExists() {
+        Log4J2LoggingRecorder.loggingEvents.clear();
+        Object message = "This is a traced Object in Log4J2.";
+        String traceId;
+
+        try (Scope scope = Tracing.getTracer().spanBuilder("test").startScopedSpan()) {
+            traceId = Tracing.getTracer().getCurrentSpan().getContext().getTraceId().toLowerBase16();
+
+            LOGGER.info(message);
+        }
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents.get(0))
+                .extracting(event -> event.getMessage().getFormattedMessage())
+                .isEqualTo("[TraceID: " + traceId + "] This is a traced Object in Log4J2.");
+    }
+
+    @Test
+    public void logNullAndTraceExists() {
+        Log4J2LoggingRecorder.loggingEvents.clear();
+        Object message = null;
+        String traceId;
+
+        try (Scope scope = Tracing.getTracer().spanBuilder("test").startScopedSpan()) {
+            traceId = Tracing.getTracer().getCurrentSpan().getContext().getTraceId().toLowerBase16();
+
+            LOGGER.info(message);
+        }
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents.get(0))
+                .extracting(event -> event.getMessage().getFormattedMessage())
+                .isEqualTo("[TraceID: " + traceId + "] null");
+    }
+
+    @Test
+    public void traceNotExists() {
+        Log4J2LoggingRecorder.loggingEvents.clear();
+        String message = "This is {}.";
+
+        LOGGER.info(message, "Log4J2");
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4J2LoggingRecorder.loggingEvents.get(0))
+                .extracting(event -> event.getMessage().getFormattedMessage())
+                .isEqualTo("This is Log4J2.");
+    }
+}

inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/special/logging/Log4JTraceIdAutoInjectorTest.java

@@ -0,0 +1,51 @@
+package rocks.inspectit.ocelot.instrumentation.special.logging;
+
+import io.opencensus.common.Scope;
+import io.opencensus.trace.Tracing;
+import org.apache.log4j.Logger;
+import org.apache.log4j.spi.LoggingEvent;
+import org.junit.jupiter.api.Test;
+import rocks.inspectit.ocelot.instrumentation.InstrumentationSysTestBase;
+import rocks.inspectit.ocelot.logging.Log4JLoggingRecorder;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class Log4JTraceIdAutoInjectorTest extends InstrumentationSysTestBase {
+
+    private static final Logger LOGGER = Logger.getLogger(Log4JTraceIdAutoInjectorTest.class.getName());
+
+    @Test
+    public void traceExists() {
+        Log4JLoggingRecorder.loggingEvents.clear();
+        String message = "This is a test.";
+        String traceId;
+
+        try (Scope scope = Tracing.getTracer().spanBuilder("test").startScopedSpan()) {
+            traceId = Tracing.getTracer().getCurrentSpan().getContext().getTraceId().toLowerBase16();
+
+            LOGGER.error(message);
+        }
+
+        assertThat(Log4JLoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4JLoggingRecorder.loggingEvents.get(0))
+                .extracting(LoggingEvent::getMessage)
+                .isEqualTo("[TraceID: " + traceId + "] " + message);
+    }
+
+    @Test
+    public void traceNotExists() {
+        Log4JLoggingRecorder.loggingEvents.clear();
+        String message = "This is a test.";
+
+        LOGGER.error(message);
+
+        assertThat(Log4JLoggingRecorder.loggingEvents)
+                .hasSize(1);
+
+        assertThat(Log4JLoggingRecorder.loggingEvents.get(0))
+                .extracting(LoggingEvent::getMessage)
+                .isEqualTo(message);
+    }
+}

inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/logging/Log4J2LoggingRecorder.java

@@ -0,0 +1,36 @@
+package rocks.inspectit.ocelot.logging;
+
+import org.apache.logging.log4j.core.Appender;
+import org.apache.logging.log4j.core.Core;
+import org.apache.logging.log4j.core.Filter;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.appender.AbstractAppender;
+import org.apache.logging.log4j.core.config.plugins.Plugin;
+import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
+import org.apache.logging.log4j.core.config.plugins.PluginElement;
+import org.apache.logging.log4j.core.config.plugins.PluginFactory;
+
+import java.util.ArrayList;
+import java.util.List;
+
+@Plugin(name = "Log4J2LoggingRecorder",
+        category = Core.CATEGORY_NAME,
+        elementType = Appender.ELEMENT_TYPE)
+public class Log4J2LoggingRecorder extends AbstractAppender {
+
+    public static final List<LogEvent> loggingEvents = new ArrayList<>();
+
+    protected Log4J2LoggingRecorder(String name, Filter filter) {
+        super(name, filter, null);
+    }
+
+    @Override
+    public void append(LogEvent event) {
+        loggingEvents.add(event);
+    }
+
+    @PluginFactory
+    public static Log4J2LoggingRecorder createAppender(@PluginAttribute("name") String name, @PluginElement("Filter") Filter filter) {
+        return new Log4J2LoggingRecorder(name, filter);
+    }
+}

inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/logging/Log4JLoggingRecorder.java

@@ -0,0 +1,27 @@
+package rocks.inspectit.ocelot.logging;
+
+import org.apache.log4j.AppenderSkeleton;
+import org.apache.log4j.spi.LoggingEvent;
+
+import java.util.ArrayList;
+import java.util.List;
+
+public class Log4JLoggingRecorder extends AppenderSkeleton {
+
+    public static final List<LoggingEvent> loggingEvents = new ArrayList<>();
+
+    @Override
+    protected void append(LoggingEvent event) {
+        loggingEvents.add(event);
+    }
+
+    @Override
+    public void close() {
+
+    }
+
+    @Override
+    public boolean requiresLayout() {
+        return false;
+    }
+}

inspectit-ocelot-agent/src/system-test/resources/config/LogCorrelationTest.yml

@@ -1,8 +1,15 @@
 
 inspectit:
   tracing:
-      log-correlation:
+    log-correlation:
+      trace-id-mdc-injection:
         enabled: true
+
+      trace-id-auto-injection:
+        enabled: true
+        prefix: "[TraceID: "
+        suffix: "] "
+
   instrumentation:
     scopes:
       LogCorrelationTest-methods:

inspectit-ocelot-agent/src/system-test/resources/log4j.properties

@@ -0,0 +1,8 @@
+log4j.rootLogger=DEBUG, recorder, stdout
+
+log4j.appender.recorder=rocks.inspectit.ocelot.logging.Log4JLoggingRecorder
+
+log4j.appender.stdout=org.apache.log4j.ConsoleAppender
+log4j.appender.stdout.Target=System.out
+log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
+log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} - %m%n

inspectit-ocelot-agent/src/system-test/resources/log4j2.xml

@@ -0,0 +1,15 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration status="DEBUG" packages="rocks.inspectit.ocelot.logging">
+    <Appenders>
+        <Console name="LogToConsole" target="SYSTEM_OUT">
+            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
+        </Console>
+        <Log4J2LoggingRecorder name="Log4J2LoggingRecorder"/>
+    </Appenders>
+    <Loggers>
+        <Root level="info">
+            <AppenderRef ref="LogToConsole"/>
+            <AppenderRef ref="Log4J2LoggingRecorder"/>
+        </Root>
+    </Loggers>
+</Configuration>

inspectit-ocelot-bootstrap/src/main/java/rocks/inspectit/ocelot/bootstrap/Instances.java

@@ -3,7 +3,9 @@
 import rocks.inspectit.ocelot.bootstrap.context.IContextManager;
 import rocks.inspectit.ocelot.bootstrap.context.noop.NoopContextManager;
 import rocks.inspectit.ocelot.bootstrap.correlation.LogTraceCorrelator;
+import rocks.inspectit.ocelot.bootstrap.correlation.TraceIdInjector;
 import rocks.inspectit.ocelot.bootstrap.correlation.noop.NoopLogTraceCorrelator;
+import rocks.inspectit.ocelot.bootstrap.correlation.noop.NoopTraceIdInjector;
 import rocks.inspectit.ocelot.bootstrap.exposed.ObjectAttachments;
 import rocks.inspectit.ocelot.bootstrap.instrumentation.IHookManager;
 import rocks.inspectit.ocelot.bootstrap.instrumentation.noop.NoopHookManager;
@@ -37,4 +39,6 @@ public class Instances {
     public static ObjectAttachments attachments = NoopObjectAttachments.INSTANCE;
 
     public static LogTraceCorrelator logTraceCorrelator = NoopLogTraceCorrelator.INSTANCE;
+
+    public static TraceIdInjector traceIdInjector = NoopTraceIdInjector.INSTANCE;
 }

inspectit-ocelot-bootstrap/src/main/java/rocks/inspectit/ocelot/bootstrap/correlation/TraceIdInjector.java

@@ -0,0 +1,16 @@
+package rocks.inspectit.ocelot.bootstrap.correlation;
+
+/**
+ * Implementations of this interface will inject the current trace id (if existing) into the given message. Normally,
+ * the message is a log format of a logging framework.
+ */
+public interface TraceIdInjector {
+
+    /**
+     * Injects the trace id (if existing) into the given message and returns the result.
+     *
+     * @param message the message to use
+     * @return the resulting object of the injection
+     */
+    Object injectTraceId(Object message);
+}

inspectit-ocelot-bootstrap/src/main/java/rocks/inspectit/ocelot/bootstrap/correlation/noop/NoopTraceIdInjector.java

@@ -0,0 +1,22 @@
+package rocks.inspectit.ocelot.bootstrap.correlation.noop;
+
+import rocks.inspectit.ocelot.bootstrap.correlation.TraceIdInjector;
+
+/**
+ * No-operation implementation of the {@link TraceIdInjector}.
+ */
+public class NoopTraceIdInjector implements TraceIdInjector {
+
+    /**
+     * Singleton instance.
+     */
+    public static final TraceIdInjector INSTANCE = new NoopTraceIdInjector();
+
+    private NoopTraceIdInjector() {
+    }
+
+    @Override
+    public Object injectTraceId(Object message) {
+        return message;
+    }
+}

inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/LogCorrelationSettings.java

@@ -3,21 +3,21 @@
 import lombok.Data;
 import lombok.NoArgsConstructor;
 
-import javax.validation.constraints.NotBlank;
+import javax.validation.Valid;
 
 @Data
 @NoArgsConstructor
 public class LogCorrelationSettings {
 
     /**
-     * Specifies whether log correlation shall be performed or not.
-     * If enabled, the currently active traceID will be published to the MDC of all log libraries.
+     * Settings for the injection of trace ids into logging MDCs.
      */
-    private boolean enabled;
+    @Valid
+    private TraceIdMDCInjectionSettings traceIdMdcInjection = new TraceIdMDCInjectionSettings();
 
     /**
-     * The key under which the traceid is placed in the MDCs.
+     * Settings for the auto injection of trace ids into log messages.
      */
-    @NotBlank
-    private String key;
+    @Valid
+    private TraceIdAutoInjectionSettings traceIdAutoInjection = new TraceIdAutoInjectionSettings();
 }

inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/TraceIdAutoInjectionSettings.java

@@ -0,0 +1,28 @@
+package rocks.inspectit.ocelot.config.model.tracing;
+
+import lombok.Data;
+import lombok.NoArgsConstructor;
+
+/**
+ * Settings for the auto injection of trace ids into log messages. The trace id will be injected into a message in the
+ * following format: [PREFIX]_trace_id_[SUFFIX]_message_
+ */
+@Data
+@NoArgsConstructor
+public class TraceIdAutoInjectionSettings {
+
+    /**
+     * Whether the auto injection is enabled.
+     */
+    private boolean enabled;
+
+    /**
+     * The used prefix.
+     */
+    private String prefix;
+
+    /**
+     * The used suffix.
+     */
+    private String suffix;
+}