open-telemetry
/
opentelemetry-java-instrumentation
mirror of https://github.com/open-telemetry/opentelemetry-java-instrumentation.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Ability to instrument logs before OTel injection into OTel appenders (#9798) 

Co-authored-by: Trask Stalnaker <trask.stalnaker@gmail.com>
This commit is contained in:
Jean Bisutti 2023-11-17 19:03:17 +01:00 committed by GitHub
parent f491250efa
commit c5cb94893b
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
19 changed files with 1184 additions and 427 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

15
instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jHelper.java
View File

@ -27,10 +27,12 @@ public final class Log4jHelper {
private static final LogEventMapper<Map<String, String>> mapper;
private static final boolean captureExperimentalAttributes;
static {
InstrumentationConfig config = InstrumentationConfig.get();
boolean captureExperimentalAttributes =
captureExperimentalAttributes =
config.getBoolean("otel.instrumentation.log4j-appender.experimental-log-attributes", false);
boolean captureMapMessageAttributes =
config.getBoolean(
@ -66,7 +68,16 @@ public final class Log4jHelper {
.build()
.logRecordBuilder();
Map<String, String> contextData = ThreadContext.getImmutableContext();
mapper.mapLogEvent(builder, message, level, marker, throwable, contextData);
String threadName = null;
long threadId = -1;
if (captureExperimentalAttributes) {
Thread currentThread = Thread.currentThread();
threadName = currentThread.getName();
threadId = currentThread.getId();
}
mapper.mapLogEvent(
builder, message, level, marker, throwable, contextData, threadName, threadId);
builder.setTimestamp(Instant.now());
builder.emit();
}

13
instrumentation/log4j/log4j-appender-2.17/library/README.md
View File

@ -93,11 +93,12 @@ Setting can be configured as XML attributes, for example:
The available settings are:
| XML Attribute | Type | Default | Description |
| ------------------------------- | ------- | ------- | --------------------------------------------------------------------------------------------------------------------- |
| `captureExperimentalAttributes` | Boolean | `false` | Enable the capture of experimental span attributes `thread.name` and `thread.id`. |
| `captureMapMessageAttributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
| `captureMarkerAttribute;` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
| `captureContextDataAttributes` | String | | Comma separated list of context data attributes to capture. Use the wildcard character `*` to capture all attributes. |
| XML Attribute | Type | Default | Description |
|---------------------------------|---------|---------|------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| `captureExperimentalAttributes` | Boolean | `false` | Enable the capture of experimental span attributes `thread.name` and `thread.id`. |
| `captureMapMessageAttributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
| `captureMarkerAttribute;` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
| `captureContextDataAttributes` | String | | Comma separated list of context data attributes to capture. Use the wildcard character `*` to capture all attributes. |
| `numLogsCapturedBeforeOtelInstall` | Integer | 1000 | Log telemetry is emitted after the initialization of the OpenTelemetry Log4j appender with an OpenTelemetry object. This setting allows you to modify the size of the cache used to replay the first logs. |
[source code attributes]: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/attributes.md#source-code-attributes

210
instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogEventToReplay.java Normal file
View File

@ -0,0 +1,210 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.log4j.appender.v2_17;
import java.util.Collections;
import java.util.Map;
import javax.annotation.Nullable;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.ThreadContext;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.apache.logging.log4j.util.ReadOnlyStringMap;
class LogEventToReplay implements LogEvent {
private static final long serialVersionUID = 1L;
// Log4j 2 reuses LogEvent object, so we make a copy of all the fields that are used during export
// in order to be able to replay the log event later.
private final String loggerName;
private final Message message;
private final Level level;
private final Instant instant;
private final Throwable thrown;
private final Marker marker;
private final ReadOnlyStringMap contextData;
private final String threadName;
private final long threadId;
LogEventToReplay(LogEvent logEvent) {
this.loggerName = logEvent.getLoggerName();
Message messageOrigin = logEvent.getMessage();
if (messageOrigin instanceof StructuredDataMessage) {
StructuredDataMessage structuredDataMessage = (StructuredDataMessage) messageOrigin;
this.message =
// Log4j 2 reuses StructuredDataMessage object
new StructuredDataMessage(
structuredDataMessage.getId(),
structuredDataMessage.getFormat(),
structuredDataMessage.getType(),
structuredDataMessage.getData());
} else if (messageOrigin instanceof StringMapMessage) {
// StringMapMessage objects are not reused by Log4j 2
this.message = messageOrigin;
} else {
this.message = new MessageCopy(logEvent.getMessage());
}
this.level = logEvent.getLevel();
this.instant = logEvent.getInstant();
this.thrown = logEvent.getThrown();
this.marker = logEvent.getMarker();
this.contextData = logEvent.getContextData();
this.threadName = logEvent.getThreadName();
this.threadId = logEvent.getThreadId();
}
@Override
public LogEvent toImmutable() {
return null;
}
@SuppressWarnings("deprecation") // Override
@Override
public Map<String, String> getContextMap() {
return Collections.emptyMap();
}
@Override
public ReadOnlyStringMap getContextData() {
return contextData;
}
@Nullable
@Override
public ThreadContext.ContextStack getContextStack() {
return null;
}
@Override
public String getLoggerFqcn() {
return null;
}
@Override
public Level getLevel() {
return level;
}
@Override
public String getLoggerName() {
return loggerName;
}
@Override
public Marker getMarker() {
return marker;
}
@Override
public Message getMessage() {
return message;
}
@Override
public long getTimeMillis() {
return 0;
}
@Override
public Instant getInstant() {
return instant;
}
@Override
public StackTraceElement getSource() {
return null;
}
@Override
public String getThreadName() {
return threadName;
}
@Override
public long getThreadId() {
return threadId;
}
@Override
public int getThreadPriority() {
return 0;
}
@Override
public Throwable getThrown() {
return thrown;
}
@Override
public ThrowableProxy getThrownProxy() {
return null;
}
@Override
public boolean isEndOfBatch() {
return false;
}
@Override
public boolean isIncludeLocation() {
return false;
}
@Override
public void setEndOfBatch(boolean endOfBatch) {}
@Override
public void setIncludeLocation(boolean locationRequired) {}
@Override
public long getNanoTime() {
return 0;
}
private static class MessageCopy implements Message {
private static final long serialVersionUID = 1L;
private final String formattedMessage;
private final String format;
private final Object[] parameters;
private final Throwable throwable;
public MessageCopy(Message message) {
this.formattedMessage = message.getFormattedMessage();
this.format = message.getFormat();
this.parameters = message.getParameters();
this.throwable = message.getThrowable();
}
@Override
public String getFormattedMessage() {
return formattedMessage;
}
@Override
public String getFormat() {
return format;
}
@Override
public Object[] getParameters() {
return parameters;
}
@Override
public Throwable getThrowable() {
return throwable;
}
}
}

88
instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppender.java
View File

@ -13,9 +13,16 @@ import io.opentelemetry.api.logs.LogRecordBuilder;
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor;
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.LogEventMapper;
import java.io.Serializable;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.ArrayBlockingQueue;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReadWriteLock;
import java.util.concurrent.locks.ReentrantReadWriteLock;
import java.util.function.BiConsumer;
import java.util.stream.Collectors;
import javax.annotation.Nullable;
@ -48,6 +55,12 @@ public class OpenTelemetryAppender extends AbstractAppender {
private final LogEventMapper<ReadOnlyStringMap> mapper;
private volatile OpenTelemetry openTelemetry;
private final BlockingQueue<LogEventToReplay> eventsToReplay;
private final AtomicBoolean replayLimitWarningLogged = new AtomicBoolean();
private final ReadWriteLock lock = new ReentrantReadWriteLock();
/**
* Installs the {@code openTelemetry} instance on any {@link OpenTelemetryAppender}s identified in
* the {@link LoggerContext}.
@ -82,6 +95,7 @@ public class OpenTelemetryAppender extends AbstractAppender {
@PluginBuilderAttribute private boolean captureMapMessageAttributes;
@PluginBuilderAttribute private boolean captureMarkerAttribute;
@PluginBuilderAttribute private String captureContextDataAttributes;
@PluginBuilderAttribute private int numLogsCapturedBeforeOtelInstall;
@Nullable private OpenTelemetry openTelemetry;
@ -121,6 +135,18 @@ public class OpenTelemetryAppender extends AbstractAppender {
return asBuilder();
}
/**
* Log telemetry is emitted after the initialization of the OpenTelemetry Logback appender with
* an {@link OpenTelemetry} object. This setting allows you to modify the size of the cache used
* to replay the logs that were emitted prior to setting the OpenTelemetry instance into the
* Logback appender.
*/
@CanIgnoreReturnValue
public B setNumLogsCapturedBeforeOtelInstall(int numLogsCapturedBeforeOtelInstall) {
this.numLogsCapturedBeforeOtelInstall = numLogsCapturedBeforeOtelInstall;
return asBuilder();
}
/** Configures the {@link OpenTelemetry} used to append logs. */
@CanIgnoreReturnValue
public B setOpenTelemetry(OpenTelemetry openTelemetry) {
@ -144,6 +170,7 @@ public class OpenTelemetryAppender extends AbstractAppender {
captureMapMessageAttributes,
captureMarkerAttribute,
captureContextDataAttributes,
numLogsCapturedBeforeOtelInstall,
openTelemetry);
}
}
@ -158,6 +185,7 @@ public class OpenTelemetryAppender extends AbstractAppender {
boolean captureMapMessageAttributes,
boolean captureMarkerAttribute,
String captureContextDataAttributes,
int numLogsCapturedBeforeOtelInstall,
OpenTelemetry openTelemetry) {
super(name, filter, layout, ignoreExceptions, properties);
@ -169,6 +197,11 @@ public class OpenTelemetryAppender extends AbstractAppender {
captureMarkerAttribute,
splitAndFilterBlanksAndNulls(captureContextDataAttributes));
this.openTelemetry = openTelemetry;
if (numLogsCapturedBeforeOtelInstall != 0) {
this.eventsToReplay = new ArrayBlockingQueue<>(numLogsCapturedBeforeOtelInstall);
} else {
this.eventsToReplay = new ArrayBlockingQueue<>(1000);
}
}
private static List<String> splitAndFilterBlanksAndNulls(String value) {
@ -186,22 +219,61 @@ public class OpenTelemetryAppender extends AbstractAppender {
* to function. See {@link #install(OpenTelemetry)} for simple installation option.
*/
public void setOpenTelemetry(OpenTelemetry openTelemetry) {
this.openTelemetry = openTelemetry;
List<LogEventToReplay> eventsToReplay = new ArrayList<>();
Lock writeLock = lock.writeLock();
writeLock.lock();
try {
// minimize scope of write lock
this.openTelemetry = openTelemetry;
this.eventsToReplay.drainTo(eventsToReplay);
} finally {
writeLock.unlock();
}
// now emit
for (LogEventToReplay eventToReplay : eventsToReplay) {
emit(openTelemetry, eventToReplay);
}
}
@SuppressWarnings("SystemOut")
@Override
public void append(LogEvent event) {
OpenTelemetry openTelemetry = this.openTelemetry;
if (openTelemetry != null) {
// optimization to avoid locking after the OpenTelemetry instance is set
emit(openTelemetry, event);
return;
}
Lock readLock = lock.readLock();
readLock.lock();
try {
openTelemetry = this.openTelemetry;
if (openTelemetry != null) {
emit(openTelemetry, event);
return;
}
LogEventToReplay logEventToReplay = new LogEventToReplay(event);
if (!eventsToReplay.offer(logEventToReplay) && !replayLimitWarningLogged.getAndSet(true)) {
String message =
"numLogsCapturedBeforeOtelInstall value of the OpenTelemetry appender is too small.";
System.err.println(message);
}
} finally {
readLock.unlock();
}
}
private void emit(OpenTelemetry openTelemetry, LogEvent event) {
String instrumentationName = event.getLoggerName();
if (instrumentationName == null || instrumentationName.isEmpty()) {
instrumentationName = "ROOT";
}
LogRecordBuilder builder =
this.openTelemetry
.getLogsBridge()
.loggerBuilder(instrumentationName)
.build()
.logRecordBuilder();
openTelemetry.getLogsBridge().loggerBuilder(instrumentationName).build().logRecordBuilder();
ReadOnlyStringMap contextData = event.getContextData();
mapper.mapLogEvent(
builder,
@ -209,7 +281,9 @@ public class OpenTelemetryAppender extends AbstractAppender {
event.getLevel(),
event.getMarker(),
event.getThrown(),
contextData);
contextData,
event.getThreadName(),
event.getThreadId());
Instant timestamp = event.getInstant();
if (timestamp != null) {

9
instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java
View File

@ -80,7 +80,9 @@ public final class LogEventMapper<T> {
Level level,
@Nullable Marker marker,
@Nullable Throwable throwable,
T contextData) {
T contextData,
String threadName,
long threadId) {
AttributesBuilder attributes = Attributes.builder();
@ -105,9 +107,8 @@ public final class LogEventMapper<T> {
captureContextDataAttributes(attributes, contextData);
if (captureExperimentalAttributes) {
Thread currentThread = Thread.currentThread();
attributes.put(SemanticAttributes.THREAD_NAME, currentThread.getName());
attributes.put(SemanticAttributes.THREAD_ID, currentThread.getId());
attributes.put(SemanticAttributes.THREAD_NAME, threadName);
attributes.put(SemanticAttributes.THREAD_ID, threadId);
}
builder.setAllAttributes(attributes.build());

243
instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java Normal file
View File

@ -0,0 +1,243 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.log4j.appender.v2_17;
import static io.opentelemetry.api.common.AttributeKey.stringKey;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies;
import static java.util.concurrent.TimeUnit.MILLISECONDS;
import io.opentelemetry.api.OpenTelemetry;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.logs.Severity;
import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.sdk.OpenTelemetrySdk;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.SdkLoggerProvider;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor;
import io.opentelemetry.sdk.resources.Resource;
import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter;
import io.opentelemetry.semconv.SemanticAttributes;
import java.time.Instant;
import java.util.List;
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.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.message.FormattedMessage;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.junit.jupiter.api.AfterAll;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.Test;
abstract class AbstractOpenTelemetryAppenderTest {
static final Logger logger = LogManager.getLogger("TestLogger");
static InMemoryLogRecordExporter logRecordExporter;
static Resource resource;
static InstrumentationScopeInfo instrumentationScopeInfo;
static OpenTelemetry openTelemetry;
void executeAfterLogsExecution() {}
@BeforeAll
static void setupAll() {
logRecordExporter = InMemoryLogRecordExporter.create();
resource = Resource.getDefault();
instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger");
SdkLoggerProvider loggerProvider =
SdkLoggerProvider.builder()
.setResource(resource)
.addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter))
.build();
openTelemetry = OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build();
}
static void generalBeforeEachSetup() {
logRecordExporter.reset();
ThreadContext.clearAll();
}
@AfterAll
static void cleanupAll() {
// This is to make sure that other test classes don't have issues with the logger provider set
OpenTelemetryAppender.install(null);
}
@Test
void initializeWithBuilder() {
OpenTelemetryAppender appender =
OpenTelemetryAppender.builder()
.setName("OpenTelemetryAppender")
.setOpenTelemetry(openTelemetry)
.build();
appender.start();
appender.append(
Log4jLogEvent.newBuilder()
.setMessage(new FormattedMessage("log message 1", (Object) null))
.build());
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList)
.satisfiesExactly(logRecordData -> assertThat(logDataList.get(0)).hasBody("log message 1"));
}
@Test
void logNoSpan() {
logger.info("log message 1");
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasAttributes(Attributes.empty());
}
@Test
void logWithSpanInvalid() {
logger.info("log message");
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0).getSpanContext()).isEqualTo(SpanContext.getInvalid());
}
@Test
void logWithExtras() {
Instant start = Instant.now();
logger.info("log message 1", new IllegalStateException("Error!"));
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasSeverity(Severity.INFO)
.hasSeverityText("INFO")
.hasAttributesSatisfyingExactly(
equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()),
equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "Error!"),
satisfies(SemanticAttributes.EXCEPTION_STACKTRACE, v -> v.contains("logWithExtras")));
assertThat(logDataList.get(0).getTimestampEpochNanos())
.isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli()))
.isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli()));
}
@Test
void logContextData() {
ThreadContext.put("key1", "val1");
ThreadContext.put("key2", "val2");
try {
logger.info("log message 1");
} finally {
ThreadContext.clearMap();
}
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.context_data.key1"), "val1"),
equalTo(stringKey("log4j.context_data.key2"), "val2"));
}
@Test
void logStringMapMessage() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
@Test
void logStringMapMessageWithSpecialAttribute() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("message", "val2");
logger.info(message);
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("val2")
.hasAttributesSatisfyingExactly(equalTo(stringKey("log4j.map_message.key1"), "val1"));
}
@Test
void testCaptureMarkerAttribute() {
String markerName = "aMarker";
Marker marker = MarkerManager.getMarker(markerName);
logger.info(marker, "Message");
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
LogRecordData logData = logDataList.get(0);
assertThat(logData.getAttributes().get(stringKey("log4j.marker"))).isEqualTo(markerName);
}
@Test
void logStructuredDataMessage() {
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("a message")
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
}

100
instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java Normal file
View File

@ -0,0 +1,100 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.log4j.appender.v2_17;
import static io.opentelemetry.api.common.AttributeKey.stringKey;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo;
import static org.assertj.core.api.Assertions.assertThat;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions;
import java.util.List;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
class LogReplayOpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest {
@BeforeEach
void setup() {
generalBeforeEachSetup();
OpenTelemetryAppender.install(null);
}
@Override
void executeAfterLogsExecution() {
OpenTelemetryAppender.install(openTelemetry);
}
@Test
void twoLogs() {
logger.info("log message 1");
logger.info(
"log message 2"); // Won't be instrumented because cache size is 1 (see log4j2.xml file)
OpenTelemetryAppender.install(openTelemetry);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
OpenTelemetryAssertions.assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1");
}
@Test
void twoLogsStringMapMessage() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);
StringMapMessage message2 = new StringMapMessage();
message2.put("key1-2", "val1-2");
message2.put("key2-2", "val2-2");
logger.info(message2); // Won't be instrumented because cache size is 1 (see log4j2.xml file)
OpenTelemetryAppender.install(openTelemetry);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
OpenTelemetryAssertions.assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
@Test
void twoLogsStructuredDataMessage() {
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);
StructuredDataMessage message2 =
new StructuredDataMessage("an id 2", "a message 2", "a type 2");
message.put("key1-2", "val1-2");
message.put("key2-2", "val2-2");
logger.info(message2); // Won't be instrumented because cache size is 1 (see log4j2.xml file)
OpenTelemetryAppender.install(openTelemetry);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
OpenTelemetryAssertions.assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("a message")
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
}

216
instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderTest.java
View File

@ -5,125 +5,36 @@
package io.opentelemetry.instrumentation.log4j.appender.v2_17;
import static io.opentelemetry.api.common.AttributeKey.stringKey;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies;
import static java.util.concurrent.TimeUnit.MILLISECONDS;
import static org.assertj.core.api.Assertions.assertThat;
import io.opentelemetry.api.OpenTelemetry;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.logs.Severity;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.context.Scope;
import io.opentelemetry.sdk.OpenTelemetrySdk;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.SdkLoggerProvider;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor;
import io.opentelemetry.sdk.resources.Resource;
import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter;
import io.opentelemetry.sdk.trace.SdkTracerProvider;
import io.opentelemetry.semconv.SemanticAttributes;
import java.time.Instant;
import java.util.List;
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.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.message.FormattedMessage;
import org.apache.logging.log4j.message.StringMapMessage;
import org.apache.logging.log4j.message.StructuredDataMessage;
import org.junit.jupiter.api.AfterAll;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
class OpenTelemetryAppenderTest {
private static final Logger logger = LogManager.getLogger("TestLogger");
private static InMemoryLogRecordExporter logRecordExporter;
private static Resource resource;
private static InstrumentationScopeInfo instrumentationScopeInfo;
private static OpenTelemetry openTelemetry;
@BeforeAll
static void setupAll() {
logRecordExporter = InMemoryLogRecordExporter.create();
resource = Resource.getDefault();
instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger");
SdkLoggerProvider loggerProvider =
SdkLoggerProvider.builder()
.setResource(resource)
.addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter))
.build();
openTelemetry = OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build();
OpenTelemetryAppender.install(openTelemetry);
}
class OpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest {
@BeforeEach
void setup() {
logRecordExporter.reset();
ThreadContext.clearAll();
}
@AfterAll
static void cleanupAll() {
// This is to make sure that other test classes don't have issues with the logger provider set
OpenTelemetryAppender.install(null);
generalBeforeEachSetup();
OpenTelemetryAppender.install(openTelemetry);
}
@Test
void initializeWithBuilder() {
OpenTelemetryAppender appender =
OpenTelemetryAppender.builder()
.setName("OpenTelemetryAppender")
.setOpenTelemetry(openTelemetry)
.build();
appender.start();
void logWithSpan() { // Does not work for log replay but it is not likely to occur because
// the log replay is related to the case where an OpenTelemetry object is not yet available
// at the time the log is executed (and if no OpenTelemetry is available, the context
// propagation can't happen)
Span span1 = runWithSpan("span1", () -> logger.info("log message"));
appender.append(
Log4jLogEvent.newBuilder()
.setMessage(new FormattedMessage("log message 1", (Object) null))
.build());
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList)
.satisfiesExactly(logRecordData -> assertThat(logDataList.get(0)).hasBody("log message 1"));
}
@Test
void logNoSpan() {
logger.info("log message 1");
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasAttributes(Attributes.empty());
}
@Test
void logWithSpan() {
Span span1 = runWithSpan("span1", () -> logger.info("log message 1"));
logger.info("log message 2");
Span span2 = runWithSpan("span2", () -> logger.info("log message 3"));
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(3);
assertThat(logDataList.get(0).getSpanContext()).isEqualTo(span1.getSpanContext());
assertThat(logDataList.get(1).getSpanContext()).isEqualTo(SpanContext.getInvalid());
assertThat(logDataList.get(2).getSpanContext()).isEqualTo(span2.getSpanContext());
}
private static Span runWithSpan(String spanName, Runnable runnable) {
@ -135,111 +46,4 @@ class OpenTelemetryAppenderTest {
}
return span;
}
@Test
void logWithExtras() {
Instant start = Instant.now();
logger.info("log message 1", new IllegalStateException("Error!"));
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasSeverity(Severity.INFO)
.hasSeverityText("INFO")
.hasAttributesSatisfyingExactly(
equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()),
equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "Error!"),
satisfies(SemanticAttributes.EXCEPTION_STACKTRACE, v -> v.contains("logWithExtras")));
assertThat(logDataList.get(0).getTimestampEpochNanos())
.isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli()))
.isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli()));
}
@Test
void logContextData() {
ThreadContext.put("key1", "val1");
ThreadContext.put("key2", "val2");
try {
logger.info("log message 1");
} finally {
ThreadContext.clearMap();
}
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.context_data.key1"), "val1"),
equalTo(stringKey("log4j.context_data.key2"), "val2"));
}
@Test
void logStringMapMessage() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("key2", "val2");
logger.info(message);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
@Test
void logStringMapMessageWithSpecialAttribute() {
StringMapMessage message = new StringMapMessage();
message.put("key1", "val1");
message.put("message", "val2");
logger.info(message);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("val2")
.hasAttributesSatisfyingExactly(equalTo(stringKey("log4j.map_message.key1"), "val1"));
}
@Test
void testCaptureMarkerAttribute() {
String markerName = "aMarker";
Marker marker = MarkerManager.getMarker(markerName);
logger.info(marker, "Message");
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
LogRecordData logData = logDataList.get(0);
assertThat(logData.getAttributes().get(stringKey("log4j.marker"))).isEqualTo(markerName);
}
@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<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
assertThat(logDataList.get(0))
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("a message")
.hasAttributesSatisfyingExactly(
equalTo(stringKey("log4j.map_message.key1"), "val1"),
equalTo(stringKey("log4j.map_message.key2"), "val2"));
}
}

2
instrumentation/log4j/log4j-appender-2.17/library/src/test/resources/log4j2.xml
View File

@ -7,7 +7,7 @@
pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} traceId: %X{trace_id} spanId: %X{span_id} flags: %X{trace_flags} - %msg%n"/>
</Console>
<!-- TODO run tests both with and without experimental log attributes -->
<OpenTelemetry name="OpenTelemetryAppender" captureMapMessageAttributes="true" captureMarkerAttribute="true" captureContextDataAttributes="*"/>
<OpenTelemetry name="OpenTelemetryAppender" numLogsCapturedBeforeOtelInstall="1" captureMapMessageAttributes="true" captureMarkerAttribute="true" captureContextDataAttributes="*"/>
</Appenders>
<Loggers>
<Logger name="TestLogger" level="All">

3
instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java
View File

@ -51,7 +51,8 @@ class LogbackInstrumentation implements TypeInstrumentation {
// logging framework delegates to another
callDepth = CallDepth.forClass(LoggerProvider.class);
if (callDepth.getAndIncrement() == 0) {
mapper().emit(GlobalOpenTelemetry.get().getLogsBridge(), event);
mapper()
.emit(GlobalOpenTelemetry.get().getLogsBridge(), event, Thread.currentThread().getId());
}
}

18
instrumentation/logback/logback-appender-1.0/library/README.md
View File

@ -93,13 +93,15 @@ Settings can be configured in `logback.xml`, for example:
The available settings are:
| XML Element | Type | Default | Description |
|---------------------------------| ------- | ------- |-----------------------------------------------------------------------------------------------------------------------------------------------|
| `captureExperimentalAttributes` | Boolean | `false` | Enable the capture of experimental span attributes `thread.name` and `thread.id`. |
| `captureCodeAttributes` | Boolean | `false` | Enable the capture of [source code attributes]. Note that capturing source code attributes at logging sites might add a performance overhead. |
| `captureMarkerAttribute` | Boolean | `false` | Enable the capture of Logback markers as attributes. |
| `captureKeyValuePairAttributes` | Boolean | `false` | Enable the capture of Logback key value pairs as attributes. |
| `captureLoggerContext` | Boolean | `false` | Enable the capture of Logback logger context properties as attributes. |
| `captureMdcAttributes` | String | | Comma separated list of MDC attributes to capture. Use the wildcard character `*` to capture all attributes. |
| XML Element | Type | Default | Description |
|---------------------------------|---------|---------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| `captureExperimentalAttributes` | Boolean | `false` | Enable the capture of experimental span attributes `thread.name` and `thread.id`. |
| `captureCodeAttributes` | Boolean | `false` | Enable the capture of [source code attributes]. Note that capturing source code attributes at logging sites might add a performance overhead. |
| `captureMarkerAttribute` | Boolean | `false` | Enable the capture of Logback markers as attributes. |
| `captureKeyValuePairAttributes` | Boolean | `false` | Enable the capture of Logback key value pairs as attributes. |
| `captureLoggerContext` | Boolean | `false` | Enable the capture of Logback logger context properties as attributes. |
| `captureMdcAttributes` | String | | Comma separated list of MDC attributes to capture. Use the wildcard character `*` to capture all attributes. |
| `numLogsCapturedBeforeOtelInstall`| Integer | 1000 | Log telemetry is emitted after the initialization of the OpenTelemetry Logback appender with an OpenTelemetry object. This setting allows you to modify the size of the cache used to replay the first logs. thread.id attribute is not captured. |
[source code attributes]: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/attributes.md#source-code-attributes

136
instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LoggingEventToReplay.java Normal file
View File

@ -0,0 +1,136 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.logback.appender.v1_0;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.IThrowableProxy;
import ch.qos.logback.classic.spi.LoggerContextVO;
import java.util.List;
import java.util.Map;
import org.slf4j.Marker;
import org.slf4j.event.KeyValuePair;
class LoggingEventToReplay implements ILoggingEvent {
private final ILoggingEvent loggingEvent;
private final long timeStamp;
private StackTraceElement[] callerData;
private String threadName;
LoggingEventToReplay(
ILoggingEvent loggingEvent,
boolean captureExperimentalAttributes,
boolean captureCodeAttributes) {
this.loggingEvent = loggingEvent;
// The values are copied because the current values are not more available when the log is
// replayed
this.timeStamp = loggingEvent.getTimeStamp();
if (captureExperimentalAttributes) {
this.threadName = loggingEvent.getThreadName();
}
if (captureCodeAttributes) {
this.callerData = loggingEvent.getCallerData();
}
}
@Override
public String getThreadName() {
return threadName;
}
@Override
public Level getLevel() {
return loggingEvent.getLevel();
}
@Override
public String getMessage() {
return loggingEvent.getMessage();
}
@Override
public Object[] getArgumentArray() {
return loggingEvent.getArgumentArray();
}
@Override
public String getFormattedMessage() {
return loggingEvent.getFormattedMessage();
}
@Override
public String getLoggerName() {
return loggingEvent.getLoggerName();
}
@Override
public LoggerContextVO getLoggerContextVO() {
return loggingEvent.getLoggerContextVO();
}
@Override
public IThrowableProxy getThrowableProxy() {
return loggingEvent.getThrowableProxy();
}
@Override
public StackTraceElement[] getCallerData() {
return callerData;
}
@Override
public boolean hasCallerData() {
return loggingEvent.hasCallerData();
}
@SuppressWarnings("deprecation") // Delegate
@Override
public Marker getMarker() {
return loggingEvent.getMarker();
}
@Override
public List<Marker> getMarkerList() {
return loggingEvent.getMarkerList();
}
@Override
public Map<String, String> getMDCPropertyMap() {
return loggingEvent.getMDCPropertyMap();
}
@SuppressWarnings("deprecation") // Delegate
@Override
public Map<String, String> getMdc() {
return loggingEvent.getMdc();
}
@Override
public long getTimeStamp() {
return timeStamp;
}
@Override
public int getNanoseconds() {
return loggingEvent.getNanoseconds();
}
@Override
public long getSequenceNumber() {
return loggingEvent.getSequenceNumber();
}
@Override
public List<KeyValuePair> getKeyValuePairs() {
return loggingEvent.getKeyValuePairs();
}
@Override
public void prepareForDeferredProcessing() {
loggingEvent.prepareForDeferredProcessing();
}
}

75
instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppender.java
View File

@ -12,8 +12,15 @@ import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.UnsynchronizedAppenderBase;
import io.opentelemetry.api.OpenTelemetry;
import io.opentelemetry.instrumentation.logback.appender.v1_0.internal.LoggingEventMapper;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.ArrayBlockingQueue;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReadWriteLock;
import java.util.concurrent.locks.ReentrantReadWriteLock;
import java.util.stream.Collectors;
import org.slf4j.ILoggerFactory;
import org.slf4j.LoggerFactory;
@ -31,6 +38,13 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
private volatile OpenTelemetry openTelemetry;
private LoggingEventMapper mapper;
private int numLogsCapturedBeforeOtelInstall = 1000;
private BlockingQueue<LoggingEventToReplay> eventsToReplay =
new ArrayBlockingQueue<>(numLogsCapturedBeforeOtelInstall);
private final AtomicBoolean replayLimitWarningLogged = new AtomicBoolean();
private final ReadWriteLock lock = new ReentrantReadWriteLock();
public OpenTelemetryAppender() {}
/**
@ -65,15 +79,40 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
captureMarkerAttribute,
captureKeyValuePairAttributes,
captureLoggerContext);
if (openTelemetry == null) {
openTelemetry = OpenTelemetry.noop();
}
eventsToReplay = new ArrayBlockingQueue<>(numLogsCapturedBeforeOtelInstall);
super.start();
}
@SuppressWarnings("SystemOut")
@Override
protected void append(ILoggingEvent event) {
mapper.emit(openTelemetry.getLogsBridge(), event);
OpenTelemetry openTelemetry = this.openTelemetry;
if (openTelemetry != null) {
// optimization to avoid locking after the OpenTelemetry instance is set
emit(openTelemetry, event);
return;
}
Lock readLock = lock.readLock();
readLock.lock();
try {
openTelemetry = this.openTelemetry;
if (openTelemetry != null) {
emit(openTelemetry, event);
return;
}
LoggingEventToReplay logEventToReplay =
new LoggingEventToReplay(event, captureExperimentalAttributes, captureCodeAttributes);
if (!eventsToReplay.offer(logEventToReplay) && !replayLimitWarningLogged.getAndSet(true)) {
String message =
"numLogsCapturedBeforeOtelInstall value of the OpenTelemetry appender is too small.";
System.err.println(message);
}
} finally {
readLock.unlock();
}
}
/**
@ -133,12 +172,38 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
}
}
/**
* Log telemetry is emitted after the initialization of the OpenTelemetry Logback appender with an
* {@link OpenTelemetry} object. This setting allows you to modify the size of the cache used to
* replay the first logs.
*/
public void setNumLogsCapturedBeforeOtelInstall(int size) {
this.numLogsCapturedBeforeOtelInstall = size;
}
/**
* Configures the {@link OpenTelemetry} used to append logs. This MUST be called for the appender
* to function. See {@link #install(OpenTelemetry)} for simple installation option.
*/
public void setOpenTelemetry(OpenTelemetry openTelemetry) {
this.openTelemetry = openTelemetry;
List<LoggingEventToReplay> eventsToReplay = new ArrayList<>();
Lock writeLock = lock.writeLock();
writeLock.lock();
try {
// minimize scope of write lock
this.openTelemetry = openTelemetry;
this.eventsToReplay.drainTo(eventsToReplay);
} finally {
writeLock.unlock();
}
// now emit
for (LoggingEventToReplay eventToReplay : eventsToReplay) {
emit(openTelemetry, eventToReplay);
}
}
private void emit(OpenTelemetry openTelemetry, ILoggingEvent event) {
mapper.emit(openTelemetry.getLogsBridge(), event, -1);
}
// copied from SDK's DefaultConfigProperties

14
instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java
View File

@ -66,14 +66,14 @@ public final class LoggingEventMapper {
captureMdcAttributes.size() == 1 && captureMdcAttributes.get(0).equals("*");
}
public void emit(LoggerProvider loggerProvider, ILoggingEvent event) {
public void emit(LoggerProvider loggerProvider, ILoggingEvent event, long threadId) {
String instrumentationName = event.getLoggerName();
if (instrumentationName == null || instrumentationName.isEmpty()) {
instrumentationName = "ROOT";
}
LogRecordBuilder builder =
loggerProvider.loggerBuilder(instrumentationName).build().logRecordBuilder();
mapLoggingEvent(builder, event);
mapLoggingEvent(builder, event, threadId);
builder.emit();
}
@ -87,7 +87,8 @@ public final class LoggingEventMapper {
* <li>Mapped diagnostic context - {@link ILoggingEvent#getMDCPropertyMap()}
* </ul>
*/
private void mapLoggingEvent(LogRecordBuilder builder, ILoggingEvent loggingEvent) {
private void mapLoggingEvent(
LogRecordBuilder builder, ILoggingEvent loggingEvent, long threadId) {
// message
String message = loggingEvent.getFormattedMessage();
if (message != null) {
@ -122,9 +123,10 @@ public final class LoggingEventMapper {
captureMdcAttributes(attributes, loggingEvent.getMDCPropertyMap());
if (captureExperimentalAttributes) {
Thread currentThread = Thread.currentThread();
attributes.put(SemanticAttributes.THREAD_NAME, currentThread.getName());
attributes.put(SemanticAttributes.THREAD_ID, currentThread.getId());
attributes.put(SemanticAttributes.THREAD_NAME, loggingEvent.getThreadName());
if (threadId != -1) {
attributes.put(SemanticAttributes.THREAD_ID, threadId);
}
}
if (captureCodeAttributes) {

198
instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/AbstractOpenTelemetryAppenderTest.java Normal file
View File

@ -0,0 +1,198 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.logback.appender.v1_0;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.core.ContextBase;
import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.logs.Severity;
import io.opentelemetry.sdk.OpenTelemetrySdk;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.SdkLoggerProvider;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor;
import io.opentelemetry.sdk.resources.Resource;
import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter;
import io.opentelemetry.semconv.SemanticAttributes;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.time.Instant;
import java.util.Arrays;
import java.util.List;
import java.util.Map;
import java.util.concurrent.TimeUnit;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
abstract class AbstractOpenTelemetryAppenderTest {
static final Logger logger = LoggerFactory.getLogger("TestLogger");
static InMemoryLogRecordExporter logRecordExporter;
static Resource resource;
static InstrumentationScopeInfo instrumentationScopeInfo;
static OpenTelemetrySdk openTelemetrySdk;
void executeAfterLogsExecution() {}
@BeforeAll
static void setupAll() {
logRecordExporter = InMemoryLogRecordExporter.create();
resource = Resource.getDefault();
instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger");
SdkLoggerProvider loggerProvider =
SdkLoggerProvider.builder()
.setResource(resource)
.addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter))
.build();
openTelemetrySdk = OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build();
// by default LoggerContext contains HOSTNAME property we clear it to start with empty context
resetLoggerContext();
}
static void resetLoggerContext() {
try {
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
Field field = ContextBase.class.getDeclaredField("propertyMap");
field.setAccessible(true);
Map<?, ?> map = (Map<?, ?>) field.get(loggerContext);
map.clear();
Method method;
try {
method = LoggerContext.class.getDeclaredMethod("syncRemoteView");
} catch (NoSuchMethodException noSuchMethodException) {
method = LoggerContext.class.getDeclaredMethod("updateLoggerContextVO");
}
method.setAccessible(true);
method.invoke(loggerContext);
} catch (Exception exception) {
throw new IllegalStateException("Failed to reset logger context", exception);
}
}
static void generalBeforeEachSetup() {
logRecordExporter.reset();
}
@Test
void logNoSpan() {
logger.info("log message 1");
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData)
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasTotalAttributeCount(4);
}
@Test
void logWithExtras() {
Instant start = Instant.now();
String markerName = "aMarker";
Marker marker = MarkerFactory.getMarker(markerName);
logger.info(marker, "log message 1", new IllegalStateException("Error!"));
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getTimestampEpochNanos())
.isGreaterThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(start.toEpochMilli()))
.isLessThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(Instant.now().toEpochMilli()));
assertThat(logData.getSeverity()).isEqualTo(Severity.INFO);
assertThat(logData.getSeverityText()).isEqualTo("INFO");
assertThat(logData.getAttributes().size())
.isEqualTo(3 + 4 + 1); // 3 exception attributes, 4 code attributes, 1 marker attribute
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(AbstractOpenTelemetryAppenderTest.class.getSimpleName() + ".java");
String codeClass = logData.getAttributes().get(SemanticAttributes.CODE_NAMESPACE);
assertThat(codeClass).isEqualTo(AbstractOpenTelemetryAppenderTest.class.getName());
String method = logData.getAttributes().get(SemanticAttributes.CODE_FUNCTION);
assertThat(method).isEqualTo("logWithExtras");
Long lineNumber = logData.getAttributes().get(SemanticAttributes.CODE_LINENO);
assertThat(lineNumber).isGreaterThan(1);
List<String> logMarker =
logData.getAttributes().get(AttributeKey.stringArrayKey("logback.marker"));
assertThat(logMarker).isEqualTo(Arrays.asList(markerName));
}
@Test
void logContextData() {
MDC.put("key1", "val1");
MDC.put("key2", "val2");
try {
logger.info("log message 1");
} finally {
MDC.clear();
}
executeAfterLogsExecution();
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(2 + 4); // 4 code attributes
assertThat(logData.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1")))
.isEqualTo("val1");
assertThat(logData.getAttributes().get(AttributeKey.stringKey("logback.mdc.key2")))
.isEqualTo("val2");
}
@Test
void logLoggerContext() {
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.putProperty("test-property", "test-value");
try {
logger.info("log message 1");
executeAfterLogsExecution();
} finally {
resetLoggerContext();
}
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(1 + 4); // 4 code attributes
assertThat(logData.getAttributes().get(AttributeKey.stringKey("test-property")))
.isEqualTo("test-value");
}
}

74
instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogReplayOpenTelemetryAppenderTest.java Normal file
View File

@ -0,0 +1,74 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.logback.appender.v1_0;
import static org.assertj.core.api.Assertions.assertThat;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.util.ContextInitializer;
import ch.qos.logback.core.spi.ContextAware;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions;
import java.net.URL;
import java.util.List;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
class LogReplayOpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest {
@BeforeEach
void setup() throws Exception {
generalBeforeEachSetup();
// to make sure we start fresh with a new OpenTelemetryAppender for each test
reloadLoggerConfiguration();
}
private static void reloadLoggerConfiguration() throws Exception {
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.reset();
try {
Class<?> configuratorClass =
Class.forName("ch.qos.logback.classic.util.DefaultJoranConfigurator");
Object configurator = configuratorClass.getConstructor().newInstance();
((ContextAware) configurator).setContext(loggerContext);
configuratorClass
.getMethod("configure", LoggerContext.class)
.invoke(configurator, loggerContext);
} catch (Exception e) {
// logback versions prior to 1.3.0
ContextInitializer ci = new ContextInitializer(loggerContext);
URL url = LogReplayOpenTelemetryAppenderTest.class.getResource("/logback-test.xml");
ContextInitializer.class.getMethod("configureByResource", URL.class).invoke(ci, url);
// by default LoggerContext contains HOSTNAME property we clear it to start with empty context
resetLoggerContext();
}
}
@Override
void executeAfterLogsExecution() {
OpenTelemetryAppender.install(openTelemetrySdk);
}
@Test
void twoLogs() {
logger.info("log message 1");
logger.info(
"log message 2"); // Won't be instrumented because cache size is 1 (see logback-test.xml
// file)
OpenTelemetryAppender.install(openTelemetrySdk);
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
OpenTelemetryAssertions.assertThat(logData)
.hasResource(resource)
.hasInstrumentationScope(instrumentationScopeInfo)
.hasBody("log message 1")
.hasTotalAttributeCount(4);
}
}

193
instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderTest.java
View File

@ -5,120 +5,43 @@
package io.opentelemetry.instrumentation.logback.appender.v1_0;
import static org.assertj.core.api.Assertions.assertThat;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.core.ContextBase;
import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.logs.Severity;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.context.Scope;
import io.opentelemetry.sdk.OpenTelemetrySdk;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.SdkLoggerProvider;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor;
import io.opentelemetry.sdk.resources.Resource;
import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter;
import io.opentelemetry.sdk.trace.SdkTracerProvider;
import io.opentelemetry.semconv.SemanticAttributes;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.time.Instant;
import java.util.Arrays;
import java.util.List;
import java.util.Map;
import java.util.concurrent.TimeUnit;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
class OpenTelemetryAppenderTest {
private static final Logger logger = LoggerFactory.getLogger("TestLogger");
private static InMemoryLogRecordExporter logRecordExporter;
private static Resource resource;
private static InstrumentationScopeInfo instrumentationScopeInfo;
@BeforeAll
static void setupAll() {
logRecordExporter = InMemoryLogRecordExporter.create();
resource = Resource.getDefault();
instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger");
SdkLoggerProvider loggerProvider =
SdkLoggerProvider.builder()
.setResource(resource)
.addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter))
.build();
OpenTelemetrySdk openTelemetrySdk =
OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build();
OpenTelemetryAppender.install(openTelemetrySdk);
// by default LoggerContext contains HOSTNAME property we clear it to start with empty context
resetLoggerContext();
}
private static void resetLoggerContext() {
try {
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
Field field = ContextBase.class.getDeclaredField("propertyMap");
field.setAccessible(true);
Map<?, ?> map = (Map<?, ?>) field.get(loggerContext);
map.clear();
Method method;
try {
method = LoggerContext.class.getDeclaredMethod("syncRemoteView");
} catch (NoSuchMethodException noSuchMethodException) {
method = LoggerContext.class.getDeclaredMethod("updateLoggerContextVO");
}
method.setAccessible(true);
method.invoke(loggerContext);
} catch (Exception exception) {
throw new IllegalStateException("Failed to reset logger context", exception);
}
}
class OpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest {
@BeforeEach
void setup() {
logRecordExporter.reset();
generalBeforeEachSetup();
OpenTelemetryAppender.install(openTelemetrySdk);
}
@Test
void logNoSpan() {
logger.info("log message 1");
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(4); // 4 code attributes
}
@Test
void logWithSpan() {
void logWithSpan() { // Does not work for log replay but it is not likely to occur because
// the log replay is related to the case where an OpenTelemetry object is not yet available
// at the time the log is executed (and if no OpenTelemetry is available, the context
// propagation can't happen)
Span span1 = runWithSpan("span1", () -> logger.info("log message 1"));
logger.info("log message 2");
executeAfterLogsExecution();
Span span2 = runWithSpan("span2", () -> logger.info("log message 3"));
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(3);
assertThat(logDataList.get(0).getSpanContext()).isEqualTo(span1.getSpanContext());
assertThat(logDataList.get(1).getSpanContext()).isEqualTo(SpanContext.getInvalid());
assertThat(logDataList.get(2).getSpanContext()).isEqualTo(span2.getSpanContext());
assertThat(logDataList.get(0)).hasSpanContext(span1.getSpanContext());
assertThat(logDataList.get(1)).hasSpanContext(SpanContext.getInvalid());
assertThat(logDataList.get(2)).hasSpanContext(span2.getSpanContext());
}
private static Span runWithSpan(String spanName, Runnable runnable) {
@ -130,94 +53,4 @@ class OpenTelemetryAppenderTest {
}
return span;
}
@Test
void logWithExtras() {
Instant start = Instant.now();
String markerName = "aMarker";
Marker marker = MarkerFactory.getMarker(markerName);
logger.info(marker, "log message 1", new IllegalStateException("Error!"));
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getTimestampEpochNanos())
.isGreaterThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(start.toEpochMilli()))
.isLessThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(Instant.now().toEpochMilli()));
assertThat(logData.getSeverity()).isEqualTo(Severity.INFO);
assertThat(logData.getSeverityText()).isEqualTo("INFO");
assertThat(logData.getAttributes().size())
.isEqualTo(3 + 4 + 1); // 3 exception attributes, 4 code attributes, 1 marker attribute
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("OpenTelemetryAppenderTest.java");
String codeClass = logData.getAttributes().get(SemanticAttributes.CODE_NAMESPACE);
assertThat(codeClass)
.isEqualTo(
"io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppenderTest");
String method = logData.getAttributes().get(SemanticAttributes.CODE_FUNCTION);
assertThat(method).isEqualTo("logWithExtras");
Long lineNumber = logData.getAttributes().get(SemanticAttributes.CODE_LINENO);
assertThat(lineNumber).isGreaterThan(1);
List<String> logMarker =
logData.getAttributes().get(AttributeKey.stringArrayKey("logback.marker"));
assertThat(logMarker).isEqualTo(Arrays.asList(markerName));
}
@Test
void logContextData() {
MDC.put("key1", "val1");
MDC.put("key2", "val2");
try {
logger.info("log message 1");
} finally {
MDC.clear();
}
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(2 + 4); // 4 code attributes
assertThat(logData.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1")))
.isEqualTo("val1");
assertThat(logData.getAttributes().get(AttributeKey.stringKey("logback.mdc.key2")))
.isEqualTo("val2");
}
@Test
void logLoggerContext() {
LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
loggerContext.putProperty("test-property", "test-value");
try {
logger.info("log message 1");
} finally {
resetLoggerContext();
}
List<LogRecordData> logDataList = logRecordExporter.getFinishedLogRecordItems();
assertThat(logDataList).hasSize(1);
LogRecordData logData = logDataList.get(0);
assertThat(logData.getResource()).isEqualTo(resource);
assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo);
assertThat(logData.getBody().asString()).isEqualTo("log message 1");
assertThat(logData.getAttributes().size()).isEqualTo(1 + 4); // 4 code attributes
assertThat(logData.getAttributes().get(AttributeKey.stringKey("test-property")))
.isEqualTo("test-value");
}
}

1
instrumentation/logback/logback-appender-1.0/library/src/test/resources/logback-test.xml
View File

@ -15,6 +15,7 @@
<captureMarkerAttribute>true</captureMarkerAttribute>
<captureLoggerContext>true</captureLoggerContext>
<captureMdcAttributes>*</captureMdcAttributes>
<numLogsCapturedBeforeOtelInstall>1</numLogsCapturedBeforeOtelInstall>
</appender>
<root level="INFO">

3
smoke-tests-otel-starter/src/test/java/io/opentelemetry/smoketest/OtelSpringStarterSmokeTest.java
View File

@ -115,6 +115,7 @@ class OtelSpringStarterSmokeTest {
LogRecordData firstLog = logs.get(0);
assertThat(firstLog.getBody().asString())
.as("Should instrument logs")
.isEqualTo("Initializing Spring DispatcherServlet 'dispatcherServlet'");
.startsWith("Starting ")
.contains(this.getClass().getSimpleName());
}
}