Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add marker attribute for Log4j 2 #6680

Merged
merged 2 commits into from
Sep 22, 2022
Merged

Add marker attribute for Log4j 2 #6680

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
607a65b
Add marker attribute for Log4j 2
jeanbisutti Sep 20, 2022
8c53497
Update instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/g…
jeanbisutti Sep 21, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
60 changes: 39 additions & 21 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/groovy/Log4j2Test.groovy
View file
Open in desktop
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)
Comment on lines -61 to +64
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is it not possible to static import here due to conflicting assertThat signatures and/or because groovy?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have tried to add a static import with IntelliJ and some assertions were failing after that.😅 After, I did not go further in this refactoring on the assertions.

} 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,26 @@ 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())
jeanbisutti marked this conversation as resolved.
Show resolved Hide resolved
}

@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
Open in desktop
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
Open in desktop
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");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logback has markers too -- do we want to encode library name in the attribute name? I'm worried that we'll run into a situation similar to #5765, perhaps it'd be better to avoid it right from the start and just name it log.marker or sth similar.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@trask Do you agree with @mateuszrzeszutek? Or would it be something we would like to discuss at the next OpenTelemetry Java + Instrumentation SIG?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mateuszrzeszutek I gave contradictory advice here: #6652 (comment)

so that it doesn't look like a spec'd attribute

I'm not sure what the best compromise here is

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like we're already prefixing MDC/context data with the library name (log4j.context_data...), so I suppose doing the same for markers is not out of place.
I guess we can merge it as it is -- we'll most likely have to rename things anyway once the log semantic conventions start to take shape.


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
Open in desktop
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