Skip to content

Commit

Permalink
Support log4j map messages (open-telemetry#4966)
Browse files Browse the repository at this point in the history 
* Support log4j map messages

* Cache attribute keys

* Review

* Add tests

* Fix test

* Codenarc

* Better tests

* Remove sysout
  • Loading branch information
@trask @RashmiRam
trask authored and RashmiRam committed May 23, 2022
1 parent e153d9f commit fc3dd03
Show file tree
Hide file tree
Showing 6 changed files with 287 additions and 11 deletions.
1 change: 1 addition & 0 deletions instrumentation/log4j/log4j-appender-2.16/javaagent/build.gradle.kts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,5 +36,6 @@ tasks {

tasks.withType<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-context-data-attributes=*")
}
73 changes: 73 additions & 0 deletions instrumentation/log4j/log4j-appender-2.16/javaagent/src/test/groovy/Log4j2Test.groovy
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,8 @@ import io.opentelemetry.semconv.trace.attributes.SemanticAttributes
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.Logger
import org.apache.logging.log4j.ThreadContext
import org.apache.logging.log4j.message.StringMapMessage
import org.apache.logging.log4j.message.StructuredDataMessage
import spock.lang.Unroll

import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace
Expand Down Expand Up @@ -117,4 +119,75 @@ class Log4j2Test extends AgentInstrumentationSpecification {
assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.context_data.key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.context_data.key2"))).isEqualTo("val2")
}

def "test string map message"() {
when:
StringMapMessage message = new StringMapMessage()
message.put("key1", "val1")
message.put("key2", "val2")
logger.info(message)

then:

await()
.untilAsserted(
() -> {
assertThat(logs).hasSize(1)
})
def log = logs.get(0)
assertThat(log.getBody().asString()).isEmpty()
assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc")
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(2)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2")
}

def "test string map message with special attribute"() {
when:
StringMapMessage message = new StringMapMessage()
message.put("key1", "val1")
message.put("message", "val2")
logger.info(message)

then:

await()
.untilAsserted(
() -> {
assertThat(logs).hasSize(1)
})
def log = logs.get(0)
assertThat(log.getBody().asString()).isEqualTo("val2")
assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc")
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(1)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
}

def "test structured data map message"() {
when:
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type")
message.put("key1", "val1")
message.put("key2", "val2")
logger.info(message)

then:

await()
.untilAsserted(
() -> {
assertThat(logs).hasSize(1)
})
def log = logs.get(0)
assertThat(log.getBody().asString()).isEqualTo("a message")
assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc")
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(2)
assertThat(log.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2")
}
}
1 change: 1 addition & 0 deletions instrumentation/log4j/log4j-appender-2.16/library/build.gradle.kts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,5 +16,6 @@ dependencies {

tasks.withType<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-context-data-attributes=*")
}
65 changes: 57 additions & 8 deletions ...n/java/io/opentelemetry/instrumentation/log4j/appender/v2_16/internal/LogEventMapper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,13 +24,20 @@
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.message.MapMessage;
import org.apache.logging.log4j.message.Message;

public final class LogEventMapper<T> {

private static final Cache<String, AttributeKey<String>> contextDataAttributeKeys =
private static final String SPECIAL_MAP_MESSAGE_ATTRIBUTE = "message";

private static final Cache<String, AttributeKey<String>> contextDataAttributeKeyCache =
Cache.bounded(100);
private static final Cache<String, AttributeKey<String>> mapMessageAttributeKeyCache =
Cache.bounded(100);

private final boolean captureMapMessageAttributes;

private final List<String> captureContextDataAttributes;

// cached as an optimization
Expand All @@ -41,6 +48,10 @@ public final class LogEventMapper<T> {
public LogEventMapper(ContextDataAccessor<T> contextDataAccessor) {
this(
contextDataAccessor,
Config.get()
.getBoolean(
"otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes",
false),
Config.get()
.getList(
"otel.instrumentation.log4j-appender.experimental.capture-context-data-attributes",
Expand All @@ -49,8 +60,12 @@ public LogEventMapper(ContextDataAccessor<T> contextDataAccessor) {

// visible for testing
LogEventMapper(
ContextDataAccessor<T> contextDataAccessor, List<String> captureContextDataAttributes) {
ContextDataAccessor<T> contextDataAccessor,
boolean captureMapMessageAttributes,
List<String> captureContextDataAttributes) {

this.contextDataAccessor = contextDataAccessor;
this.captureMapMessageAttributes = captureMapMessageAttributes;
this.captureContextDataAttributes = captureContextDataAttributes;
this.captureAllContextDataAttributes =
captureContextDataAttributes.size() == 1 && captureContextDataAttributes.get(0).equals("*");
Expand All @@ -76,17 +91,15 @@ public void mapLogEvent(
@Nullable Instant timestamp,
T contextData) {

if (message != null) {
builder.setBody(message.getFormattedMessage());
}
AttributesBuilder attributes = Attributes.builder();

captureMessage(builder, attributes, message);

if (level != null) {
builder.setSeverity(levelToSeverity(level));
builder.setSeverityText(level.name());
}

AttributesBuilder attributes = Attributes.builder();

if (throwable != null) {
setThrowable(attributes, throwable);
}
Expand All @@ -105,6 +118,42 @@ public void mapLogEvent(
}
}

// visible for testing
void captureMessage(LogBuilder builder, AttributesBuilder attributes, Message message) {
if (message == null) {
return;
}
if (!(message instanceof MapMessage)) {
builder.setBody(message.getFormattedMessage());
return;
}

MapMessage<?, ?> mapMessage = (MapMessage<?, ?>) message;

String body = mapMessage.getFormat();
boolean checkSpecialMapMessageAttribute = (body == null || body.isEmpty());
if (checkSpecialMapMessageAttribute) {
body = mapMessage.get(SPECIAL_MAP_MESSAGE_ATTRIBUTE);
}

if (body != null && !body.isEmpty()) {
builder.setBody(body);
}

if (captureMapMessageAttributes) {
mapMessage.forEach(
(key, value) -> {
if (value != null
&& (!checkSpecialMapMessageAttribute
|| !key.equals(SPECIAL_MAP_MESSAGE_ATTRIBUTE))) {
attributes.put(
mapMessageAttributeKeyCache.computeIfAbsent(key, AttributeKey::stringKey),
value.toString());
}
});
}
}

// visible for testing
void captureContextDataAttributes(AttributesBuilder attributes, T contextData) {

Expand All @@ -128,7 +177,7 @@ void captureContextDataAttributes(AttributesBuilder attributes, T contextData) {
}

public static AttributeKey<String> getContextDataAttributeKey(String key) {
return contextDataAttributeKeys.computeIfAbsent(
return contextDataAttributeKeyCache.computeIfAbsent(
key, k -> AttributeKey.stringKey("log4j.context_data." + k));
}

Expand Down
55 changes: 55 additions & 0 deletions ...o/opentelemetry/instrumentation/log4j/appender/v2_16/OpenTelemetryAppenderConfigTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
Expand Down Expand Up @@ -148,4 +150,57 @@ void logContextData() {
assertThat(logData.getAttributes().get(AttributeKey.stringKey("log4j.context_data.key2")))
.isEqualTo("val2");
}

@Test
void logStringMapMessage() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);

List<LogData> logDataList = logExporter.getFinishedLogItems();
assertThat(logDataList).hasSize(1);
LogData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationLibraryInfo()).isEqualTo(instrumentationLibraryInfo);
assertThat(logData.getBody().asString()).isEmpty();
assertThat(logData.getAttributes().size()).isEqualTo(2);
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1");
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2");
}

@Test
void logStringMapMessageWithSpecialAttribute() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("message", "val2");
logger.info(message);

List<LogData> logDataList = logExporter.getFinishedLogItems();
assertThat(logDataList).hasSize(1);
LogData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationLibraryInfo()).isEqualTo(instrumentationLibraryInfo);
assertThat(logData.getBody().asString()).isEqualTo("val2");
assertThat(logData.getAttributes().size()).isEqualTo(1);
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1");
}

@Test
void logStructuredDataMessage() {
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);

List<LogData> logDataList = logExporter.getFinishedLogItems();
assertThat(logDataList).hasSize(1);
LogData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationLibraryInfo()).isEqualTo(instrumentationLibraryInfo);
assertThat(logData.getBody().asString()).isEqualTo("a message");
assertThat(logData.getAttributes().size()).isEqualTo(2);
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1");
assertThat(logData.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2");
}
}
Loading

0 comments on commit fc3dd03

Please sign in to comment.