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

Merged
merged 14 commits into from
Sep 13, 2022
Merged

Add code attributes for Logback #6591

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
14 commits
Select commit Hold shift + click to select a range
7528865
Add code attributes for Logback
jeanbisutti Sep 12, 2022
1ebe9f4
Rename property
jeanbisutti Sep 12, 2022
d9bbf85
Add a note about performance
jeanbisutti Sep 12, 2022
52f05e8
Merge remote-tracking branch 'upstream/main' into logback-stack-elements
trask Sep 12, 2022
8d1cf4d
Add null check on file name
jeanbisutti Sep 13, 2022
df6d85a
Add check on line number
jeanbisutti Sep 13, 2022
6d9d706
Fix test following new behavior
jeanbisutti Sep 13, 2022
5db9ded
spotless
jeanbisutti Sep 13, 2022
887fe3a
Update instrumentation/logback/logback-appender-1.0/library/src/main/…
jeanbisutti Sep 13, 2022
e363a1f
Fix test
jeanbisutti Sep 13, 2022
dba1c75
Adapt test for Java 18
jeanbisutti Sep 13, 2022
8037182
Merge remote-tracking branch 'upstream/main' into logback-stack-elements
trask Sep 13, 2022
33b65c5
codenarc
trask Sep 13, 2022
4dd5c6b
Test fix
jeanbisutti Sep 13, 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/logback/logback-appender-1.0/javaagent/build.gradle.kts
View file
Open in desktop
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")
}
7 changes: 6 additions & 1 deletion ...a/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackSingletons.java
View file
Open in desktop
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
13 changes: 10 additions & 3 deletions instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,13 @@ class LogbackTest extends AgentInstrumentationSpecification {
waitForTraces(1)
}

String jvmVersion = System.getProperty("java.vm.specification.version")
Copy link
Member

Choose a reason for hiding this comment

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

can we use this instead? (this is the property we check for java version in the agent)

Suggested change
String jvmVersion = System.getProperty("java.vm.specification.version")
String jvmVersion = System.getProperty("java.version")

Copy link
Member Author

Choose a reason for hiding this comment

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

No. System.getProperty("java.version") contains the minor JVM version and the number parsing just after will fail

int codeAttributes = 3
boolean jvmVersionGreaterThanOrEqualTo18 = !jvmVersion.startsWith("1.8") && Integer.parseInt(jvmVersion) >= 18
if (jvmVersionGreaterThanOrEqualTo18) {
codeAttributes = 4 // Java 18 specificity on line number (lineNumber > 0 check)
Copy link
Member

Choose a reason for hiding this comment

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

I wonder if this is because of groovy, I would be surprised to see different behavior for a regular Java class, I may try to convert this test to Java after merging it

Copy link
Member Author

Choose a reason for hiding this comment

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

Line number is negative for Java <= 17 and this Groovy test, everything is fine for the library test based on JUnit 5

}

if (severity != null) {
await()
.untilAsserted(
Expand All @@ -56,12 +63,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 + codeAttributes)
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 + codeAttributes)
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 +130,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
17 changes: 16 additions & 1 deletion ...in/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppender.java
View file
Open in desktop
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
23 changes: 22 additions & 1 deletion ...a/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java
View file
Open in desktop
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 > 0) {
attributes.put(SemanticAttributes.CODE_LINENO, lineNumber);
}
}
}

builder.setAllAttributes(attributes.build());

// span context
Expand Down
21 changes: 17 additions & 4 deletions .../opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderConfigTest.java
View file
Open in desktop
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
6 changes: 3 additions & 3 deletions .../opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapperTest.java
View file
Open in desktop
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
1 change: 1 addition & 0 deletions instrumentation/logback/logback-appender-1.0/library/src/test/resources/logback-test.xml
View file
Open in desktop
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