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.

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 code attributes for Logback #6591

Merged
merged 14 commits into from
Sep 13, 2022
Original file line number Diff line number Diff line change
Expand Up @@ -54,4 +54,5 @@ tasks.withType<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-mdc-attributes=*")
jvmArgs("-Dotel.instrumentation.logback-appender.experimental-log-attributes=true")
jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-code-attributes=true")
}
Original file line number Diff line number Diff line change
Expand Up @@ -21,12 +21,17 @@ public final class LogbackSingletons {
boolean captureExperimentalAttributes =
config.getBoolean(
"otel.instrumentation.logback-appender.experimental-log-attributes", false);
boolean captureCodeAttributes =
config.getBoolean(
"otel.instrumentation.logback-appender.experimental.capture-code-attributes", false);
List<String> captureMdcAttributes =
config.getList(
"otel.instrumentation.logback-appender.experimental.capture-mdc-attributes",
emptyList());

mapper = new LoggingEventMapper(captureExperimentalAttributes, captureMdcAttributes);
mapper =
new LoggingEventMapper(
captureExperimentalAttributes, captureMdcAttributes, captureCodeAttributes);
}

public static LoggingEventMapper mapper() {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -56,12 +56,12 @@ class LogbackTest extends AgentInstrumentationSpecification {
assertThat(log.getSeverity()).isEqualTo(severity)
assertThat(log.getSeverityText()).isEqualTo(severityText)
if (exception) {
assertThat(log.getAttributes().size()).isEqualTo(5)
assertThat(log.getAttributes().size()).isEqualTo(5 + 4) // 4 code attributes
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(LogbackTest.name)
} else {
assertThat(log.getAttributes().size()).isEqualTo(2)
assertThat(log.getAttributes().size()).isEqualTo(2 + 4) // 4 code attributes
Copy link
Member

Choose a reason for hiding this comment

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

Can you add code attributes assertions to the javaagent test too?

Copy link
Member Author

Choose a reason for hiding this comment

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

Because of the nature of the Groovy test, the attribute values are not very readable:

file = NativeMethodAccessorImpl.java
codeClass = jdk.internal.reflect.NativeMethodAccessorImpl
method = invoke0

The attribute values are checked in a library test.

Copy link
Member

Choose a reason for hiding this comment

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

Eh, forgot that was groovy. Nevermind then 👍

Copy link
Member

Choose a reason for hiding this comment

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

ya, it would be nice to have validation that the attributes are working inside of the Java agent as well, but can get to that later, I've opened #6604 to track

assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull()
Expand Down Expand Up @@ -123,7 +123,7 @@ class LogbackTest extends AgentInstrumentationSpecification {
assertThat(log.getInstrumentationScopeInfo().getName()).isEqualTo("abc")
assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
assertThat(log.getSeverityText()).isEqualTo("INFO")
assertThat(log.getAttributes().size()).isEqualTo(4)
assertThat(log.getAttributes().size()).isEqualTo(3 + 3) // 3 code attributes
assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1"))).isEqualTo("val1")
assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key2"))).isEqualTo("val2")
assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
new LogEmitterProviderHolder();

private volatile boolean captureExperimentalAttributes = false;
private volatile boolean captureCodeAttributes = false;
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 wanted first that the captureCodeAttributes property would be an AtomicBoolean, but I have noticed after that captureExperimentalAttributes is a boolean, so I keep the same way of doing

private volatile List<String> captureMdcAttributes = emptyList();

private volatile LoggingEventMapper mapper;
Expand All @@ -33,7 +34,9 @@ public OpenTelemetryAppender() {}

@Override
public void start() {
mapper = new LoggingEventMapper(captureExperimentalAttributes, captureMdcAttributes);
mapper =
new LoggingEventMapper(
captureExperimentalAttributes, captureMdcAttributes, captureCodeAttributes);
super.start();
}

Expand Down Expand Up @@ -62,6 +65,18 @@ public void setCaptureExperimentalAttributes(boolean captureExperimentalAttribut
this.captureExperimentalAttributes = captureExperimentalAttributes;
}

/**
* Sets whether the code attributes (file name, class name, method name and line number) should be
* set to logs. Enabling these attributes can potentially impact performance (see
* https://logback.qos.ch/manual/layouts.html).
*
* @param captureCodeAttributes To enable or disable the code attributes (file name, class name,
* method name and line number)
*/
public void setCaptureCodeAttributes(boolean captureCodeAttributes) {
this.captureCodeAttributes = captureCodeAttributes;
}

/** Configures the {@link MDC} attributes that will be copied to logs. */
public void setCaptureMdcAttributes(String attributes) {
if (attributes != null) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -34,10 +34,14 @@ public final class LoggingEventMapper {
private final boolean captureExperimentalAttributes;
private final List<String> captureMdcAttributes;
private final boolean captureAllMdcAttributes;
private final boolean captureCodeAttributes;

public LoggingEventMapper(
boolean captureExperimentalAttributes, List<String> captureMdcAttributes) {
boolean captureExperimentalAttributes,
List<String> captureMdcAttributes,
boolean captureCodeAttributes) {
this.captureExperimentalAttributes = captureExperimentalAttributes;
this.captureCodeAttributes = captureCodeAttributes;
this.captureMdcAttributes = captureMdcAttributes;
this.captureAllMdcAttributes =
captureMdcAttributes.size() == 1 && captureMdcAttributes.get(0).equals("*");
Expand Down Expand Up @@ -104,6 +108,23 @@ private void mapLoggingEvent(LogRecordBuilder builder, ILoggingEvent loggingEven
attributes.put(SemanticAttributes.THREAD_ID, currentThread.getId());
}

if (captureCodeAttributes) {
StackTraceElement[] callerData = loggingEvent.getCallerData();
if (callerData != null && callerData.length > 0) {
StackTraceElement firstStackElement = callerData[0];
String fileName = firstStackElement.getFileName();
if (fileName != null) {
attributes.put(SemanticAttributes.CODE_FILEPATH, fileName);
}
attributes.put(SemanticAttributes.CODE_NAMESPACE, firstStackElement.getClassName());
attributes.put(SemanticAttributes.CODE_FUNCTION, firstStackElement.getMethodName());
int lineNumber = firstStackElement.getLineNumber();
if (lineNumber != -1) {
jeanbisutti marked this conversation as resolved.
Show resolved Hide resolved
attributes.put(SemanticAttributes.CODE_LINENO, lineNumber);
}
}
}

builder.setAllAttributes(attributes.build());

// span context
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,6 @@
import static org.assertj.core.api.AssertionsForInterfaceTypes.assertThat;

import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.context.Scope;
Expand Down Expand Up @@ -71,7 +70,7 @@ void logNoSpan() {
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes()).isEqualTo(Attributes.empty());
assertThat(logData.getAttributes().size()).isEqualTo(4); // 4 code attributes
}

@Test
Expand Down Expand Up @@ -115,13 +114,27 @@ void logWithExtras() {
.isLessThan(TimeUnit.MILLISECONDS.toNanos(Instant.now().toEpochMilli()));
assertThat(logData.getSeverity()).isEqualTo(Severity.INFO);
assertThat(logData.getSeverityText()).isEqualTo("INFO");
assertThat(logData.getAttributes().size()).isEqualTo(3);
assertThat(logData.getAttributes().size()).isEqualTo(3 + 4); // 4 code attributes
Copy link
Member

Choose a reason for hiding this comment

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

WDYT about refactoring this to use OpenTelemetryAssertions and AttributesAssert? Would be way more terse than the current code

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 was not aware about these classes. Thanks! I have a first look at the OpenTelemetryAssertions and AttributesAssert classes. From what I have seen, I have not the feeling that the assertions would be shorter and easier to read (for example the assertAttributes method of AttributesAssert requires a Map). Maybe I could look at this thing more in depth and propose potential improvements in another PR?

Copy link
Member

Choose a reason for hiding this comment

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

Sure, that sounds fine 👍

assertThat(logData.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE))
.isEqualTo(IllegalStateException.class.getName());
assertThat(logData.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE))
.isEqualTo("Error!");
assertThat(logData.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE))
.contains("logWithExtras");

String file = logData.getAttributes().get(SemanticAttributes.CODE_FILEPATH);
assertThat(file).isEqualTo("OpenTelemetryAppenderConfigTest.java");

String codeClass = logData.getAttributes().get(SemanticAttributes.CODE_NAMESPACE);
assertThat(codeClass)
.isEqualTo(
"io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppenderConfigTest");

String method = logData.getAttributes().get(SemanticAttributes.CODE_FUNCTION);
assertThat(method).isEqualTo("logWithExtras");

Long lineNumber = logData.getAttributes().get(SemanticAttributes.CODE_LINENO);
assertThat(lineNumber).isGreaterThan(1);
}

@Test
Expand All @@ -140,7 +153,7 @@ void logContextData() {
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(2);
assertThat(logData.getAttributes().size()).isEqualTo(2 + 4); // 4 code attributes
AssertionsForClassTypes.assertThat(
logData.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1")))
.isEqualTo("val1");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ class LoggingEventMapperTest {
@Test
void testDefault() {
// given
LoggingEventMapper mapper = new LoggingEventMapper(false, emptyList());
LoggingEventMapper mapper = new LoggingEventMapper(false, emptyList(), false);
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
Expand All @@ -38,7 +38,7 @@ void testDefault() {
@Test
void testSome() {
// given
LoggingEventMapper mapper = new LoggingEventMapper(false, singletonList("key2"));
LoggingEventMapper mapper = new LoggingEventMapper(false, singletonList("key2"), false);
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
Expand All @@ -55,7 +55,7 @@ void testSome() {
@Test
void testAll() {
// given
LoggingEventMapper mapper = new LoggingEventMapper(false, singletonList("*"));
LoggingEventMapper mapper = new LoggingEventMapper(false, singletonList("*"), false);
Map<String, String> contextData = new HashMap<>();
contextData.put("key1", "value1");
contextData.put("key2", "value2");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
<appender name="OpenTelemetry"
class="io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender">
<captureExperimentalAttributes>false</captureExperimentalAttributes>
<captureCodeAttributes>true</captureCodeAttributes>
<captureMdcAttributes>*</captureMdcAttributes>
</appender>

Expand Down