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
2 changes: 2 additions & 0 deletions instrumentation/log4j/log4j-2-common/testing/build.gradle.kts
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,8 @@ plugins {
dependencies {
api(project(":testing-common"))

api("io.opentelemetry:opentelemetry-sdk-logs:1.9.0-alpha")
Copy link
Contributor

Choose a reason for hiding this comment

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

Don't think we need version here since we apply BOM for io.opentelemetry. Similar for all usages

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes, I'm just waiting for this project to update its BOM dependency on 1.9.0 and then will drop the version here.


api("org.apache.logging.log4j:log4j-core:2.7")

implementation("com.google.guava:guava")
Expand Down
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
69 changes: 57 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 a mounted span into
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
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,43 @@ 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:/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);
```

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`.
4 changes: 4 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,15 @@ plugins {
}

dependencies {
api("io.opentelemetry:opentelemetry-sdk-logs:1.9.0-alpha")
Copy link
Contributor

Choose a reason for hiding this comment

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

That will make all clients of this library instrumentation depend on SDK. I assume all users must depend only on API.

Copy link
Member Author

Choose a reason for hiding this comment

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

Users need to call OpenTelemetryLog4j.initialize(SdkLogEmitterProvider) to wire opentelemetry into the appender so the log SDK is actually part of this module's API.

Copy link
Member Author

Choose a reason for hiding this comment

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

But this reminds me that I need to update the readme to show usage!

Copy link
Contributor

Choose a reason for hiding this comment

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

@iNikem Yeah - we have open-telemetry/opentelemetry-java#3807 to track fixing this.

Copy link
Contributor

Choose a reason for hiding this comment

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

Sleeping on this, I realized we can keep this code here by making this compileOnly - anyone adding the appender has to add the SDK to their classpath themselves.

Copy link
Contributor

Choose a reason for hiding this comment

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

Though I still think it might be simpler to continue to prototype with the code in the SDK repo. What do you think?

Copy link
Contributor

Choose a reason for hiding this comment

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

I'm definitely wary about adding an API API to support this. I think compileOnly and a reflective check for the presence of an SDK is a better way to go until we have a spec for a new logging API.

Copy link
Member Author

@jack-berg jack-berg Nov 16, 2021

Choose a reason for hiding this comment

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

compileOnly dependency on the SDK sounds reasonable to me, and potentially a path forward for all appenders.

Though I still think it might be simpler to continue to prototype with the code in the SDK repo.

Prototyping in the SDK has the advantage that the SDK and the appender can develop in lockstep, rather than the appender waiting on SDK releases, which is nice. But I think a lot of the SDK flux has been flushed out (of course assuming no significant changes to the experimental log spec) and so I don't expect to see much value from having the appender in the SDK.


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("org.mockito:mockito-core")
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,139 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_13_2;

import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SPAN_ID;
import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_FLAGS;
import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_ID;

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.List;
import java.util.Map;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.util.ReadOnlyStringMap;

final class LogEventMapper {

// Visible for testing
static final AttributeKey<String> ATTR_LOGGER_NAME = AttributeKey.stringKey("logger.name");
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't see any semantic conventions for logs defined yet, can we leave them out until they're defined?

https:/open-telemetry/opentelemetry-specification/tree/main/specification/logs/semantic_conventions

Copy link
Contributor

Choose a reason for hiding this comment

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

If leaving any, I guess logger.name, throwable.name, throwable.message are the only ones I'd keep as they may be necessary for playing with a prototype, but others seem too detailed, or unclear (e.g., I'm not familiar with term ndc)

Copy link
Member Author

@jack-berg jack-berg Nov 15, 2021

Choose a reason for hiding this comment

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

ndc = Nested Diagnostic Context

Nested diagnostic context is thread context that acts like a stack. You push items onto it, and pop them off. Mapped diagnostic context is thread context that acts like a map. Frankly, I haven't used Nested Diagnostic Context, and have only used Mapped Diagnostic Context in a limited way in applications I've written.

I took the stance of making sure that all data in the log4j2 data model somehow was mapped into the otel log data model. You're suggesting the opposite, where only a limited part of the log4j2 data model is mapped. I see pros and cons of each stance:

  • If we only do a partial mapping of fields well defined in semantic conventions, then we're less likely to make breaking changes, though we can't eliminate breaking changes since there are no stable semantic conventions. We're also going to disappoint folks using parts of the log4j2 data model that are unmapped.
  • If we do a fully mapping, we basically guarantee breaking changes, but at least all the data gets mapped. And by at least making an attempt at mapping each field we can provide better feedback for the semantic conventions.

Personally, I prefer the full mapping approach published in an "alpha" artifact. Definitely interested in other perspectives on this though.

Copy link
Contributor

Choose a reason for hiding this comment

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

I've seen it's easier to add an attribute and not really go anywhere in the spec with it than the opposite. By not including too much, we can hear about what users really need and then build the spec around it, rather than being ad-hoc. While I don't like to disappoint folks, actually hearing about that disappointment is very valuable feedback.

Copy link
Member Author

Choose a reason for hiding this comment

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

That resonates with me. Also, if we were to do a complete mapping and the required semantic conventions never materialized, we may have to pull support for that mapping, which would be an unpleasant breaking change for users.

Updated to a minimalist mapping in new commit.

static final AttributeKey<String> ATTR_THREAD_NAME = AttributeKey.stringKey("thread.name");
static final AttributeKey<Long> ATTR_THREAD_ID = AttributeKey.longKey("thread.id");
static final AttributeKey<Long> ATTR_THREAD_PRIORITY = AttributeKey.longKey("thread.priority");
static final AttributeKey<String> ATTR_THROWABLE_NAME = AttributeKey.stringKey("throwable.name");
static final AttributeKey<String> ATTR_THROWABLE_MESSAGE =
AttributeKey.stringKey("throwable.message");
static final AttributeKey<List<String>> ATTR_NDC = AttributeKey.stringArrayKey("ndc");
static final AttributeKey<String> ATTR_FQCN = AttributeKey.stringKey("fqcn");
static final AttributeKey<String> ATTR_MARKER = AttributeKey.stringKey("marker");

static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {
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.

}

// logger
attributes.put(ATTR_LOGGER_NAME, logEvent.getLoggerName());

// fully qualified class name
Copy link
Contributor

Choose a reason for hiding this comment

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

Hmm - I wonder what this is, I thought the only "class name" type of thing is the logger name, if you derive it from a class. Otherwise each log message would be quite expensive

Copy link
Member Author

Choose a reason for hiding this comment

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

This test demonstrates the value. In that case it was org.apache.logging.log4j.spi.AbstractLogger. Not sure how useful it is, but as mentioned here, my stance was to map everything.

attributes.put(ATTR_FQCN, logEvent.getLoggerFqcn());

// thread
attributes.put(ATTR_THREAD_NAME, logEvent.getThreadName());
attributes.put(ATTR_THREAD_ID, logEvent.getThreadId());
attributes.put(ATTR_THREAD_PRIORITY, logEvent.getThreadPriority());

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

// marker
Marker marker = logEvent.getMarker();
if (marker != null) {
attributes.put(ATTR_MARKER, marker.getName());
}

// nested diagnostic context
List<String> contextStackList = logEvent.getContextStack().asList();
if (contextStackList.size() > 0) {
attributes.put(ATTR_NDC, contextStackList);
}

// mapped diagnostic context (included span context)
ReadOnlyStringMap contextData = logEvent.getContextData();
if (contextData != null) {
Map<String, String> contextMap = contextData.toMap();
if (contextMap != null) {
// Remove context fields placed by OpenTelemetryContextDataProvider to avoid duplicating
// trace context fields in attributes
contextMap.remove(TRACE_ID);
contextMap.remove(SPAN_ID);
contextMap.remove(TRACE_FLAGS);
builder.setContext(Context.current());

contextMap.forEach(attributes::put);
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't think we should fill arbitrary attributes, I don't think we ever do anything similar for spans

Copy link
Member Author

Choose a reason for hiding this comment

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

Kind of related to the the conversation about doing a complete mapping or not.

Not filling arbitrary attributes from mapped diagnostic context is limiting the usefulness of the log4j2 api. It means if you want to use otel logs in a more "machine generated events" type of way, that you'd want to use the otel log sdk in your application instead of the log4j2 api.

Copy link
Contributor

Choose a reason for hiding this comment

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

I think we'd generally use baggage for more arbitrary attributes? Though we haven't even specced it for spans. But I'd still suggest keeping things smaller for now to make sure the spec grows rather than going all in

}
}

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;
}
throw new IllegalStateException("Unrecognized level " + level.name());
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
}

private LogEventMapper() {}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,76 @@
/*
* 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.LogEmitter;
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 newBuilder() {
jack-berg marked this conversation as resolved.
Show resolved Hide resolved
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<LogEmitter> logEmitterRef = 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) {
LogEmitter logEmitter = logEmitterRef.get();
if (logEmitter == null) {
// appender hasn't been initialized
return;
}
LogBuilder builder = logEmitter.logBuilder();
LogEventMapper.mapLogEvent(builder, event);
builder.emit();
}

void initialize(LogEmitter logEmitter) {
if (!logEmitterRef.compareAndSet(null, logEmitter)) {
throw new IllegalStateException("OpenTelemetryAppender has already been initialized.");
}
}
}
Loading