Skip to content

Commit

Permalink
Add marker attribute for Log4j 2 (open-telemetry#6680)
Browse files Browse the repository at this point in the history 
Co-authored-by: Mateusz Rzeszutek <mrzeszutek@splunk.com>
  • Loading branch information
@jeanbisutti @LironKS
2 people authored and LironKS committed Dec 4, 2022
1 parent 0fb047c commit ebc4646
Show file tree
Hide file tree
Showing 9 changed files with 115 additions and 33 deletions.
1 change: 1 addition & 0 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,4 +40,5 @@ tasks.withType<Test>().configureEach {
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-context-data-attributes=*")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true")
}
4 changes: 3 additions & 1 deletion ...elemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
import net.bytebuddy.matcher.ElementMatcher;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.message.Message;

class Log4jAppenderInstrumentation implements TypeInstrumentation {
Expand Down Expand Up @@ -60,14 +61,15 @@ public static class LogAdvice {
public static void methodEnter(
@Advice.This Logger logger,
@Advice.Argument(0) Level level,
@Advice.Argument(1) Marker marker,
@Advice.Argument(4) Message message,
@Advice.Argument(5) Throwable t,
@Advice.Local("otelCallDepth") CallDepth callDepth) {
// need to track call depth across all loggers in order to avoid double capture when one
// logging framework delegates to another
callDepth = CallDepth.forClass(LogEmitterProvider.class);
if (callDepth.getAndIncrement() == 0) {
Log4jHelper.capture(logger, level, message, t);
Log4jHelper.capture(logger, level, marker, message, t);
}
}

Expand Down
10 changes: 8 additions & 2 deletions ...ain/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jHelper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
import javax.annotation.Nullable;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.ThreadContext;
import org.apache.logging.log4j.message.Message;

Expand All @@ -34,6 +35,9 @@ public final class Log4jHelper {
config.getBoolean(
"otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes",
false);
boolean captureMarkerAttribute =
config.getBoolean(
"otel.instrumentation.log4j-appender.experimental.capture-marker-attribute", false);
List<String> captureContextDataAttributes =
config.getList(
"otel.instrumentation.log4j-appender.experimental.capture-context-data-attributes",
Expand All @@ -44,18 +48,20 @@ public final class Log4jHelper {
ContextDataAccessorImpl.INSTANCE,
captureExperimentalAttributes,
captureMapMessageAttributes,
captureMarkerAttribute,
captureContextDataAttributes);
}

public static void capture(Logger logger, Level level, Message message, Throwable throwable) {
public static void capture(
Logger logger, Level level, Marker marker, Message message, Throwable throwable) {
String instrumentationName = logger.getName();
if (instrumentationName == null || instrumentationName.isEmpty()) {
instrumentationName = "ROOT";
}
LogRecordBuilder builder =
AgentLogEmitterProvider.get().logEmitterBuilder(instrumentationName).build().logBuilder();
Map<String, String> contextData = ThreadContext.getImmutableContext();
mapper.mapLogEvent(builder, message, level, throwable, contextData);
mapper.mapLogEvent(builder, message, level, marker, throwable, contextData);
builder.emit();
}

Expand Down
61 changes: 40 additions & 21 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/groovy/Log4j2Test.groovy
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,12 +3,13 @@
* SPDX-License-Identifier: Apache-2.0
*/

import io.opentelemetry.api.common.AttributeKey
import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification
import io.opentelemetry.sdk.logs.data.Severity
import io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions
import io.opentelemetry.semconv.trace.attributes.SemanticAttributes
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.Logger
import org.apache.logging.log4j.MarkerManager
import org.apache.logging.log4j.ThreadContext
import org.apache.logging.log4j.message.StringMapMessage
import org.apache.logging.log4j.message.StructuredDataMessage
Expand Down Expand Up @@ -58,17 +59,17 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getSeverityText()).isEqualTo(severityText)
if (exception) {
assertThat(log.getAttributes().size()).isEqualTo(5)
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isEqualTo(IllegalStateException.getName())
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isEqualTo("hello")
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(Log4j2Test.name)
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.getName())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.EXCEPTION_MESSAGE, "hello")
OpenTelemetryAssertions.assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(Log4j2Test.name)
} else {
assertThat(log.getAttributes().size()).isEqualTo(2)
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull()
}
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())
if (parent) {
assertThat(log.getSpanContext()).isEqualTo(traces.get(0).get(0).getSpanContext())
} else {
Expand Down Expand Up @@ -119,10 +120,10 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(4)
assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.context_data.key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.context_data.key2"))).isEqualTo("val2")
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("log4j.context_data.key1", "val1")
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("log4j.context_data.key2", "val2")
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())
}

def "test string map message"() {
Expand All @@ -145,10 +146,10 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(4)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2")
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("key1", "val1")
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("key2", "val2")
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())
}

def "test string map message with special attribute"() {
Expand All @@ -171,9 +172,9 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(3)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("key1", "val1")
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName())
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())
}

def "test structured data map message"() {
Expand All @@ -196,9 +197,27 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(4)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2")
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
OpenTelemetryAssertions.assertThat(log.getAttributes())
.containsEntry("key1","val1")
.containsEntry("key2", "val2")
.containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName())
.containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())
}

@Unroll
def "marker test"() {
def markerName = "aMarker"
def marker = MarkerManager.getMarker(markerName)
when:
logger.info(marker, "message")

then:
await()
.untilAsserted(
() -> {
assertThat(logs).hasSize(1)
def log = logs.get(0)
OpenTelemetryAssertions.assertThat(log.getAttributes()).containsEntry("log4j.marker", markerName)
})
}
}
21 changes: 20 additions & 1 deletion ...ain/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppender.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,7 @@ static class Builder<B extends Builder<B>> extends AbstractAppender.Builder<B>

@PluginBuilderAttribute private boolean captureExperimentalAttributes;
@PluginBuilderAttribute private boolean captureMapMessageAttributes;
@PluginBuilderAttribute private boolean captureMarkerAttribute;
@PluginBuilderAttribute private String captureContextDataAttributes;

/**
Expand All @@ -77,6 +78,16 @@ public B setCaptureMapMessageAttributes(boolean captureMapMessageAttributes) {
return asBuilder();
}

/**
* Sets whether the marker attribute should be set to logs.
*
* @param captureMarkerAttribute To enable or disable the marker attribute
*/
public B setCaptureMarkerAttribute(boolean captureMarkerAttribute) {
this.captureMarkerAttribute = captureMarkerAttribute;
return asBuilder();
}

/** Configures the {@link ThreadContext} attributes that will be copied to logs. */
public B setCaptureContextDataAttributes(String captureContextDataAttributes) {
this.captureContextDataAttributes = captureContextDataAttributes;
Expand All @@ -93,6 +104,7 @@ public OpenTelemetryAppender build() {
getPropertyArray(),
captureExperimentalAttributes,
captureMapMessageAttributes,
captureMarkerAttribute,
captureContextDataAttributes);
}
}
Expand All @@ -105,6 +117,7 @@ private OpenTelemetryAppender(
Property[] properties,
boolean captureExperimentalAttributes,
boolean captureMapMessageAttributes,
boolean captureMarkerAttribute,
String captureContextDataAttributes) {

super(name, filter, layout, ignoreExceptions, properties);
Expand All @@ -113,6 +126,7 @@ private OpenTelemetryAppender(
ContextDataAccessorImpl.INSTANCE,
captureExperimentalAttributes,
captureMapMessageAttributes,
captureMarkerAttribute,
splitAndFilterBlanksAndNulls(captureContextDataAttributes));
}

Expand All @@ -136,7 +150,12 @@ public void append(LogEvent event) {
logEmitterProviderHolder.get().logEmitterBuilder(instrumentationName).build().logBuilder();
ReadOnlyStringMap contextData = event.getContextData();
mapper.mapLogEvent(
builder, event.getMessage(), event.getLevel(), event.getThrown(), contextData);
builder,
event.getMessage(),
event.getLevel(),
event.getMarker(),
event.getThrown(),
contextData);

Instant timestamp = event.getInstant();
if (timestamp != null) {
Expand Down
14 changes: 14 additions & 0 deletions ...n/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
import java.util.List;
import javax.annotation.Nullable;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.message.MapMessage;
import org.apache.logging.log4j.message.Message;
Expand All @@ -35,22 +36,27 @@ public final class LogEventMapper<T> {
private static final Cache<String, AttributeKey<String>> mapMessageAttributeKeyCache =
Cache.bounded(100);

private static final AttributeKey<String> LOG_MARKER = AttributeKey.stringKey("log4j.marker");

private final ContextDataAccessor<T> contextDataAccessor;

private final boolean captureExperimentalAttributes;
private final boolean captureMapMessageAttributes;
private final boolean captureMarkerAttribute;
private final List<String> captureContextDataAttributes;
private final boolean captureAllContextDataAttributes;

public LogEventMapper(
ContextDataAccessor<T> contextDataAccessor,
boolean captureExperimentalAttributes,
boolean captureMapMessageAttributes,
boolean captureMarkerAttribute,
List<String> captureContextDataAttributes) {

this.contextDataAccessor = contextDataAccessor;
this.captureExperimentalAttributes = captureExperimentalAttributes;
this.captureMapMessageAttributes = captureMapMessageAttributes;
this.captureMarkerAttribute = captureMarkerAttribute;
this.captureContextDataAttributes = captureContextDataAttributes;
this.captureAllContextDataAttributes =
captureContextDataAttributes.size() == 1 && captureContextDataAttributes.get(0).equals("*");
Expand All @@ -72,13 +78,21 @@ public void mapLogEvent(
LogRecordBuilder builder,
Message message,
Level level,
@Nullable Marker marker,
@Nullable Throwable throwable,
T contextData) {

AttributesBuilder attributes = Attributes.builder();

captureMessage(builder, attributes, message);

if (captureMarkerAttribute) {
if (marker != null) {
String markerName = marker.getName();
attributes.put(LOG_MARKER, markerName);
}
}

if (level != null) {
builder.setSeverity(levelToSeverity(level));
builder.setSeverityText(level.name());
Expand Down
15 changes: 15 additions & 0 deletions ...o/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderConfigTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,8 @@
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.MarkerManager;
import org.apache.logging.log4j.ThreadContext;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
Expand Down Expand Up @@ -184,6 +186,19 @@ void logStringMapMessageWithSpecialAttribute() {
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1");
}

@Test
void testCaptureMarkerAttribute() {
String markerName = "aMarker";
Marker marker = MarkerManager.getMarker(markerName);

logger.info(marker, "Message");

List<LogData> logDataList = logExporter.getFinishedLogItems();
LogData logData = logDataList.get(0);
assertThat(logData.getAttributes().get(AttributeKey.stringKey("log4j.marker")))
.isEqualTo(markerName);
}

@Test
void logStructuredDataMessage() {
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
Expand Down
Loading

0 comments on commit ebc4646

Please sign in to comment.