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

Prototype Log4j2 Appender #4375

Merged
merged 12 commits into from
Nov 29, 2021
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ import io.opentelemetry.instrumentation.test.InstrumentationSpecification
import org.apache.logging.log4j.LogManager

abstract class Log4j2Test extends InstrumentationSpecification {
def cleanup() {
def setup() {
ListAppender.get().clearEvents()
}

Expand Down
72 changes: 60 additions & 12 deletions instrumentation/log4j/log4j-2.13.2/library/README.md
Original file line number Diff line number Diff line change
@@ -1,15 +1,8 @@
# Log4j 2 Integration

This module integrates instrumentation with Log4j 2 by injecting the trace ID and span ID from a
mounted span into
Log4j's [context data](https://logging.apache.org/log4j/2.x/manual/thread-context.html).

**Note**: Depending on your application, you may run into a [critical bug](https://issues.apache.org/jira/browse/LOG4J2-2838)
with Log4j 2.13.2. If log messages show a `NullPointerException` when adding this instrumentation,
please update to 2.13.3 or higher. The only change between 2.13.2 and 2.13.3 is the fix to this
issue.
This module provides Log4j2 extensions related to OpenTelemetry.

To use it, just add the module to your application's runtime classpath.
To use it, add the module to your application's runtime classpath.

**Maven**

Expand All @@ -33,14 +26,26 @@ dependencies {
}
```

Log4j will automatically pick up our integration and will have these keys added to the context when
a log statement is made when a span is active.
## OpenTelemetry Context Data Provider

`OpenTelemetryContextDataProvider` implements the Log4j2 `ContextDataProvider` SPI, and injects the
trace ID and span ID from an active span into
Log4j's [context data](https://logging.apache.org/log4j/2.x/manual/thread-context.html).

**Note**: Depending on your application, you may run into
a [critical bug](https://issues.apache.org/jira/browse/LOG4J2-2838)
with Log4j 2.13.2. If log messages show a `NullPointerException` when adding this instrumentation,
please update to 2.13.3 or higher. The only change between 2.13.2 and 2.13.3 is the fix to this
issue.

Log4j will automatically pick up the integration when you include this module. The following keys
will be added to the context when a log statement is made when a span is active:

- `trace_id`
- `span_id`
- `trace_flags`

You can use these keys when defining an appender in your `log4j.xml` configuration, for example
You can use these keys when defining an appender in your `log4j.xml` configuration, for example:

```xml
<?xml version="1.0" encoding="UTF-8"?>
Expand All @@ -58,3 +63,46 @@ You can use these keys when defining an appender in your `log4j.xml` configurati
</Loggers>
</Configuration>
```

## OpenTelemetry Appender

`OpenTelemetryAppender` is a Log4j2 [appender](https://logging.apache.org/log4j/2.x/manual/appenders.html) that can be used to forward log events to the [OpenTelemetry Log SDK](https://github.com/open-telemetry/opentelemetry-java/tree/main/sdk/logs).

The following demonstrates how you might configure the appender in your `log4j.xml` configuration:

```xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" packages="io.opentelemetry.instrumentation.log4j.v2_13_2">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout 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>
<OpenTelemetry name="OpenTelemetryAppender" />
</Appenders>
<Loggers>
<Root>
<AppenderRef ref="OpenTelemetryAppender" level="All" />
<AppenderRef ref="Console" level="All" />
</Root>
</Loggers>
</Configuration>
```

Next, associate the `OpenTelemetryAppender` with a `SdkLogEmitterProvider` in your application:

```
SdkLogEmitterProvider logEmitterProvider =
SdkLogEmitterProvider.builder()
.setResource(Resource.create(...))
.addLogProcessor(...)
.build();
OpenTelemetryLog4j.initialize(logEmitterProvider);
```

**Note:** In order to initialize the `OpenTelemetryAppender` your application must depend on the
OpenTelemetry log sdk (`io.opentelemetry:opentelemetry-sdk-logs`).

In this example Log4j2 logs will be sent to both the console appender and
the `OpenTelemetryAppender`, which will drop the logs until `OpenTelemetryLog4j.initialize(..)` is
called. Once initialized, logs will be emitted to a `LogEmitter` obtained from
the `SdkLogEmitterProvider`.
5 changes: 5 additions & 0 deletions instrumentation/log4j/log4j-2.13.2/library/build.gradle.kts
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,16 @@ plugins {
}

dependencies {
compileOnly("io.opentelemetry:opentelemetry-sdk-logs")

library("org.apache.logging.log4j:log4j-core:2.13.2")

// Library instrumentation cannot be applied to 2.13.2 due to a bug in Log4J. The agent works
// around it.
testLibrary("org.apache.logging.log4j:log4j-core:2.13.3")

testImplementation(project(":instrumentation:log4j:log4j-2-common:testing"))
testImplementation("io.opentelemetry:opentelemetry-sdk-logs")

testImplementation("org.mockito:mockito-core")
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,102 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_13_2;

import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.common.AttributesBuilder;
import io.opentelemetry.context.Context;
import io.opentelemetry.sdk.logs.LogBuilder;
import io.opentelemetry.sdk.logs.data.Severity;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.message.Message;

final class LogEventMapper {

// Visible for testing
static final AttributeKey<String> ATTR_THROWABLE_MESSAGE =
AttributeKey.stringKey("throwable.message");

/**
* Map the {@link LogEvent} data model onto the {@link LogBuilder}. Unmapped fields include:
*
* <ul>
* <li>Fully qualified class name - {@link LogEvent#getLoggerFqcn()}
* <li>Thread name - {@link LogEvent#getThreadName()}
* <li>Thread id - {@link LogEvent#getThreadId()}
* <li>Thread priority - {@link LogEvent#getThreadPriority()}
* <li>Thread priority - {@link LogEvent#getThreadPriority()}
* <li>Thrown details (stack trace, class name) - {@link LogEvent#getThrown()}
* <li>Marker - {@link LogEvent#getMarker()}
* <li>Nested diagnostic context - {@link LogEvent#getContextStack()}
* <li>Mapped diagnostic context - {@link LogEvent#getContextData()}
* </ul>
*/
static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {
// TODO: map the LogEvent more completely when semantic conventions allow it
AttributesBuilder attributes = Attributes.builder();

// message
Message message = logEvent.getMessage();
if (message != null) {
builder.setBody(message.getFormattedMessage());
}

// time
Instant instant = logEvent.getInstant();
if (instant != null) {
builder.setEpoch(
TimeUnit.MILLISECONDS.toNanos(instant.getEpochMillisecond())
+ instant.getNanoOfMillisecond(),
TimeUnit.NANOSECONDS);
}

// level
Level level = logEvent.getLevel();
if (level != null) {
builder.setSeverity(levelToSeverity(level));
builder.setSeverityText(logEvent.getLevel().name());
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
builder.setSeverityText(logEvent.getLevel().name());
builder.setSeverityText(level.name());

And shouldn't this text come from our severity and not logging framework level?

Copy link
Member Author

Choose a reason for hiding this comment

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

From the spec, the severity text field "is the original string representation of the severity as it is known at the source".

But this does bring up the point that I have made a number of subjective decisions in mapping between the Log4j2 LogEvent data model and the otel log data model. Please take a close look at the attribute name's I've chosen for various things and let me know if you agree / disagree.

}

// throwable
Throwable throwable = logEvent.getThrown();
if (throwable != null) {
attributes.put(ATTR_THROWABLE_MESSAGE, throwable.getMessage());
}

// span context
builder.setContext(Context.current());

builder.setAttributes(attributes.build());
}

private static Severity levelToSeverity(Level level) {
switch (level.getStandardLevel()) {
case ALL:
return Severity.TRACE;
case TRACE:
return Severity.TRACE2;
case DEBUG:
return Severity.DEBUG;
case INFO:
return Severity.INFO;
case WARN:
return Severity.WARN;
case ERROR:
return Severity.ERROR;
case FATAL:
return Severity.FATAL;
case OFF:
return Severity.UNDEFINED_SEVERITY_NUMBER;
}
return Severity.UNDEFINED_SEVERITY_NUMBER;
}

private LogEventMapper() {}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,78 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_13_2;

import io.opentelemetry.sdk.logs.LogBuilder;
import io.opentelemetry.sdk.logs.SdkLogEmitterProvider;
import java.io.Serializable;
import java.util.concurrent.atomic.AtomicReference;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.Core;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.Property;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory;

@Plugin(
name = OpenTelemetryAppender.PLUGIN_NAME,
category = Core.CATEGORY_NAME,
elementType = Appender.ELEMENT_TYPE)
public class OpenTelemetryAppender extends AbstractAppender {

static final String PLUGIN_NAME = "OpenTelemetry";

@PluginBuilderFactory
public static <B extends Builder<B>> B builder() {
return new Builder<B>().asBuilder();
}

static class Builder<B extends Builder<B>> extends AbstractAppender.Builder<B>
implements org.apache.logging.log4j.core.util.Builder<OpenTelemetryAppender> {

@Override
public OpenTelemetryAppender build() {
OpenTelemetryAppender appender =
new OpenTelemetryAppender(
getName(), getLayout(), getFilter(), isIgnoreExceptions(), getPropertyArray());
OpenTelemetryLog4j.registerInstance(appender);
return appender;
}
}

private final AtomicReference<SdkLogEmitterProvider> sdkLogEmitterProviderRef =
new AtomicReference<>();

private OpenTelemetryAppender(
String name,
Layout<? extends Serializable> layout,
Filter filter,
boolean ignoreExceptions,
Property[] properties) {
super(name, filter, layout, ignoreExceptions, properties);
}

@Override
public void append(LogEvent event) {
SdkLogEmitterProvider logEmitterProvider = sdkLogEmitterProviderRef.get();
if (logEmitterProvider == null) {
// appender hasn't been initialized
return;
}
LogBuilder builder =
logEmitterProvider.logEmitterBuilder(event.getLoggerName()).build().logBuilder();
LogEventMapper.mapLogEvent(builder, event);
builder.emit();
}

void initialize(SdkLogEmitterProvider sdkLogEmitterProvider) {
if (!sdkLogEmitterProviderRef.compareAndSet(null, sdkLogEmitterProvider)) {
throw new IllegalStateException("OpenTelemetryAppender has already been initialized.");
}
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,64 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_13_2;

import io.opentelemetry.sdk.logs.SdkLogEmitterProvider;
import java.util.ArrayList;
import java.util.List;
import javax.annotation.Nullable;
import javax.annotation.concurrent.GuardedBy;

public final class OpenTelemetryLog4j {

private static final Object lock = new Object();

@GuardedBy("lock")
private static SdkLogEmitterProvider sdkLogEmitterProvider;

@GuardedBy("lock")
@Nullable
private static Throwable initializeCaller;

@GuardedBy("lock")
private static final List<OpenTelemetryAppender> APPENDERS = new ArrayList<>();

public static void initialize(SdkLogEmitterProvider sdkLogEmitterProvider) {
Copy link
Member

Choose a reason for hiding this comment

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

How is this going to work as a javaagent instrumentation? In the agent we keep all the SDK classes hidden in the agent classloader, they're basically unavailable from the application classloader. The agent won't be able to register its emitterProvider in the application's OpenTelemetryLog4j class.
Was the idea about "log appender api" completely scrapped? What happened with that?

Copy link
Contributor

Choose a reason for hiding this comment

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

Copy link
Member Author

Choose a reason for hiding this comment

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

Took a stab at extracting out the appender API here.

List<OpenTelemetryAppender> instances;
synchronized (lock) {
if (OpenTelemetryLog4j.sdkLogEmitterProvider != null) {
throw new IllegalStateException(
"OpenTelemetryLog4j.initialize has already been called. OpenTelemetryLog4j.initialize "
+ "must be called only once. Previous invocation set to cause of this exception.",
initializeCaller);
}
OpenTelemetryLog4j.sdkLogEmitterProvider = sdkLogEmitterProvider;
instances = new ArrayList<>(APPENDERS);
initializeCaller = new Throwable();
}
for (OpenTelemetryAppender instance : instances) {
instance.initialize(sdkLogEmitterProvider);
}
}

static void registerInstance(OpenTelemetryAppender appender) {
synchronized (lock) {
if (sdkLogEmitterProvider != null) {
appender.initialize(sdkLogEmitterProvider);
}
APPENDERS.add(appender);
}
}

// Visible for testing
static void resetForTest() {
synchronized (lock) {
sdkLogEmitterProvider = null;
APPENDERS.clear();
}
}

private OpenTelemetryLog4j() {}
}
Loading