Support log4j map messages (#4966)

* Support log4j map messages

* Cache attribute keys

* Review

* Add tests

* Fix test

* Codenarc

* Better tests

* Remove sysout
This commit is contained in:
Trask Stalnaker 2022-01-06 12:02:12 -08:00 committed by GitHub
parent acaa5e687a
commit 07ce0b5909
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 287 additions and 11 deletions

View File

@ -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=*")
}

View File

@ -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
@ -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")
}
}

View File

@ -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=*")
}

View File

@ -24,12 +24,19 @@ import javax.annotation.Nullable;
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;
@ -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",
@ -49,8 +60,12 @@ public final class LogEventMapper<T> {
// 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("*");
@ -76,17 +91,15 @@ public final class LogEventMapper<T> {
@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);
}
@ -105,6 +118,42 @@ public final class LogEventMapper<T> {
}
}
// 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) {
@ -128,7 +177,7 @@ public final class LogEventMapper<T> {
}
public static AttributeKey<String> getContextDataAttributeKey(String key) {
return contextDataAttributeKeys.computeIfAbsent(
return contextDataAttributeKeyCache.computeIfAbsent(
key, k -> AttributeKey.stringKey("log4j.context_data." + k));
}

View File

@ -29,6 +29,8 @@ import java.util.concurrent.TimeUnit;
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;
@ -148,4 +150,57 @@ class OpenTelemetryAppenderConfigTest {
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");
}
}

View File

@ -9,14 +9,21 @@ import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.asser
import static java.util.Collections.emptyList;
import static java.util.Collections.singletonList;
import static org.assertj.core.api.Assertions.entry;
import static org.mockito.ArgumentMatchers.anyString;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.never;
import static org.mockito.Mockito.verify;
import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.common.AttributesBuilder;
import io.opentelemetry.instrumentation.api.appender.LogBuilder;
import java.util.HashMap;
import java.util.Map;
import java.util.function.BiConsumer;
import javax.annotation.Nullable;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.junit.Test;
public class LogEventMapperTest {
@ -25,7 +32,7 @@ public class LogEventMapperTest {
public void testDefault() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, emptyList());
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, false, emptyList());
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
@ -42,7 +49,7 @@ public class LogEventMapperTest {
public void testSome() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, singletonList("key2"));
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, false, singletonList("key2"));
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
@ -60,7 +67,7 @@ public class LogEventMapperTest {
public void testAll() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, singletonList("*"));
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, false, singletonList("*"));
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
@ -76,6 +83,96 @@ public class LogEventMapperTest {
entry(AttributeKey.stringKey("log4j.context_data.key2"), "value2"));
}
@Test
public void testCaptureMapMessageDisabled() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, false, singletonList("*"));
StringMapMessage message = new StringMapMessage();
message.put("key1", "value1");
message.put("message", "value2");
LogBuilder logBuilder = mock(LogBuilder.class);
AttributesBuilder attributes = Attributes.builder();
// when
mapper.captureMessage(logBuilder, attributes, message);
// then
verify(logBuilder).setBody("value2");
assertThat(attributes.build()).isEmpty();
}
@Test
public void testCaptureMapMessageWithSpecialAttribute() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, true, singletonList("*"));
StringMapMessage message = new StringMapMessage();
message.put("key1", "value1");
message.put("message", "value2");
LogBuilder logBuilder = mock(LogBuilder.class);
AttributesBuilder attributes = Attributes.builder();
// when
mapper.captureMessage(logBuilder, attributes, message);
// then
verify(logBuilder).setBody("value2");
assertThat(attributes.build()).containsOnly(entry(AttributeKey.stringKey("key1"), "value1"));
}
@Test
public void testCaptureMapMessageWithoutSpecialAttribute() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, true, singletonList("*"));
StringMapMessage message = new StringMapMessage();
message.put("key1", "value1");
message.put("key2", "value2");
LogBuilder logBuilder = mock(LogBuilder.class);
AttributesBuilder attributes = Attributes.builder();
// when
mapper.captureMessage(logBuilder, attributes, message);
// then
verify(logBuilder, never()).setBody(anyString());
assertThat(attributes.build())
.containsOnly(
entry(AttributeKey.stringKey("key1"), "value1"),
entry(AttributeKey.stringKey("key2"), "value2"));
}
@Test
public void testCaptureStructuredDataMessage() {
// given
LogEventMapper<Map<String, String>> mapper =
new LogEventMapper<>(ContextDataAccessorImpl.INSTANCE, true, singletonList("*"));
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
message.put("key1", "value1");
message.put("message", "value2");
LogBuilder logBuilder = mock(LogBuilder.class);
AttributesBuilder attributes = Attributes.builder();
// when
mapper.captureMessage(logBuilder, attributes, message);
// then
verify(logBuilder).setBody("a message");
assertThat(attributes.build())
.containsOnly(
entry(AttributeKey.stringKey("key1"), "value1"),
entry(AttributeKey.stringKey("message"), "value2"));
}
private enum ContextDataAccessorImpl implements ContextDataAccessor<Map<String, String>> {
INSTANCE;