Skip to content

Commit

Permalink
Add log4j2 appender javaagent instrumentation (open-telemetry#4944)
Browse files Browse the repository at this point in the history
* log4j2

* Spotless

* Target 2.16 for javaagent instrumentation and share

* review feedback

* Add comment

* Remove unnecessary configuration

* Fix comment
  • Loading branch information
trask authored and RashmiRam committed May 23, 2022
1 parent 67b5c3b commit 816514d
Show file tree
Hide file tree
Showing 11 changed files with 301 additions and 17 deletions.
Original file line number Diff line number Diff line change
@@ -0,0 +1,35 @@
plugins {
id("otel.javaagent-instrumentation")
}

muzzle {
pass {
group.set("org.apache.logging.log4j")
module.set("log4j-core")
versions.set("[2.11.0,)")
assertInverse.set(true)
}
}

dependencies {
library("org.apache.logging.log4j:log4j-core:2.16.0")

compileOnly(project(":instrumentation-api-appender"))

implementation(project(":instrumentation:log4j:log4j-appender-2.16:library"))

testImplementation("org.awaitility:awaitility")

// this is needed for the async logging test
testImplementation("com.lmax:disruptor:3.4.2")
}

tasks {
val testAsync by registering(Test::class) {
jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector")
}

named<Test>("test") {
dependsOn(testAsync)
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,79 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_16;

import static io.opentelemetry.javaagent.extension.matcher.AgentElementMatchers.extendsClass;
import static io.opentelemetry.javaagent.extension.matcher.AgentElementMatchers.hasClassesNamed;
import static net.bytebuddy.matcher.ElementMatchers.isMethod;
import static net.bytebuddy.matcher.ElementMatchers.isProtected;
import static net.bytebuddy.matcher.ElementMatchers.isPublic;
import static net.bytebuddy.matcher.ElementMatchers.named;
import static net.bytebuddy.matcher.ElementMatchers.takesArgument;
import static net.bytebuddy.matcher.ElementMatchers.takesArguments;

import io.opentelemetry.instrumentation.api.appender.LogEmitterProvider;
import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
import io.opentelemetry.javaagent.instrumentation.api.CallDepth;
import net.bytebuddy.asm.Advice;
import net.bytebuddy.description.type.TypeDescription;
import net.bytebuddy.matcher.ElementMatcher;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.Message;

class Log4jAppenderInstrumentation implements TypeInstrumentation {

@Override
public ElementMatcher<TypeDescription> typeMatcher() {
return extendsClass(named("org.apache.logging.log4j.spi.AbstractLogger"));
}

@Override
public ElementMatcher<ClassLoader> classLoaderOptimization() {
return hasClassesNamed("org.apache.logging.log4j.spi.AbstractLogger");
}

@Override
public void transform(TypeTransformer transformer) {
transformer.applyAdviceToMethod(
isMethod()
.and(isProtected().or(isPublic()))
.and(named("log"))
.and(takesArguments(6))
.and(takesArgument(0, named("org.apache.logging.log4j.Level")))
.and(takesArgument(1, named("org.apache.logging.log4j.Marker")))
.and(takesArgument(2, String.class))
.and(takesArgument(3, StackTraceElement.class))
.and(takesArgument(4, named("org.apache.logging.log4j.message.Message")))
.and(takesArgument(5, Throwable.class)),
Log4jAppenderInstrumentation.class.getName() + "$LogAdvice");
}

@SuppressWarnings("unused")
public static class LogAdvice {

@Advice.OnMethodEnter(suppress = Throwable.class)
public static void methodEnter(
@Advice.This final Logger logger,
@Advice.Argument(0) final Level level,
@Advice.Argument(4) final Message message,
@Advice.Argument(5) final Throwable t,
@Advice.Local("otelCallDepth") CallDepth callDepth) {
// need to track call depth across all loggers in order to avoid double capture when one
// logging framework delegates to another
callDepth = CallDepth.forClass(LogEmitterProvider.class);
if (callDepth.getAndIncrement() == 0) {
Log4jHelper.capture(logger, level, message, t);
}
}

@Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class)
public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth) {
callDepth.decrementAndGet();
}
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_16;

import static java.util.Collections.singletonList;

import com.google.auto.service.AutoService;
import io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule;
import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
import java.util.List;

@AutoService(InstrumentationModule.class)
public class Log4jAppenderInstrumentationModule extends InstrumentationModule {

public Log4jAppenderInstrumentationModule() {
super("log4j-appender", "log4j-appender-2.16");
}

@Override
public List<TypeInstrumentation> typeInstrumentations() {
return singletonList(new Log4jAppenderInstrumentation());
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.javaagent.instrumentation.log4j.appender.v2_16;

import io.opentelemetry.instrumentation.api.appender.GlobalLogEmitterProvider;
import io.opentelemetry.instrumentation.api.appender.LogBuilder;
import io.opentelemetry.instrumentation.log4j.appender.v2_16.internal.LogEventMapper;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.Message;

public final class Log4jHelper {

public static void capture(Logger logger, Level level, Message message, Throwable throwable) {

LogBuilder builder =
GlobalLogEmitterProvider.get().logEmitterBuilder(logger.getName()).build().logBuilder();

LogEventMapper.setBody(builder, message);
LogEventMapper.setSeverity(builder, level);
LogEventMapper.setThrowable(builder, throwable);
LogEventMapper.setContext(builder);

builder.emit();
}

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

import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification
import io.opentelemetry.sdk.logs.data.Severity
import io.opentelemetry.semconv.trace.attributes.SemanticAttributes
import org.apache.logging.log4j.LogManager
import org.apache.logging.log4j.Logger
import spock.lang.Unroll

import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace
import static org.assertj.core.api.Assertions.assertThat
import static org.awaitility.Awaitility.await

class Log4j2Test extends AgentInstrumentationSpecification {

private static final Logger logger = LogManager.getLogger("abc")

@Unroll
def "test method=#testMethod with exception=#exception and parent=#parent"() {
when:
if (parent) {
runUnderTrace("parent") {
if (exception) {
logger."$testMethod"("xyz", new IllegalStateException("hello"))
} else {
logger."$testMethod"("xyz")
}
}
} else {
if (exception) {
logger."$testMethod"("xyz", new IllegalStateException("hello"))
} else {
logger."$testMethod"("xyz")
}
}

then:
if (parent) {
waitForTraces(1)
}

if (severity != null) {
await()
.untilAsserted(
() -> {
assertThat(logs).hasSize(1)
})
def log = logs.get(0)
assertThat(log.getBody().asString()).isEqualTo("xyz")
assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc")
assertThat(log.getSeverity()).isEqualTo(severity)
assertThat(log.getSeverityText()).isEqualTo(severityText)
if (exception) {
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isEqualTo(IllegalStateException.class.getName())
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isEqualTo("hello")
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(Log4j2Test.name)
} else {
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull()
assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull()
}
if (parent) {
assertThat(log.getSpanContext()).isEqualTo(traces.get(0).get(0).getSpanContext())
} else {
assertThat(log.getSpanContext().isValid()).isFalse()
}
} else {
Thread.sleep(500) // sleep a bit just to make sure no log is captured
logs.size() == 0
}

where:
[args, exception, parent] << [
[
["debug", null, null],
["info", Severity.INFO, "INFO"],
["warn", Severity.WARN, "WARN"],
["error", Severity.ERROR, "ERROR"]
],
[true, false],
[true, false]
].combinations()

testMethod = args[0]
severity = args[1]
severityText = args[2]
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE Configuration>
<Configuration status="WARN">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
Original file line number Diff line number Diff line change
Expand Up @@ -3,10 +3,11 @@
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_16;
package io.opentelemetry.instrumentation.log4j.appender.v2_16;

import io.opentelemetry.instrumentation.api.appender.GlobalLogEmitterProvider;
import io.opentelemetry.instrumentation.api.appender.LogBuilder;
import io.opentelemetry.instrumentation.log4j.appender.v2_16.internal.LogEventMapper;
import java.io.Serializable;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.Core;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_16;
package io.opentelemetry.instrumentation.log4j.appender.v2_16.internal;

import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.common.AttributesBuilder;
Expand All @@ -19,7 +19,7 @@
import org.apache.logging.log4j.core.time.Instant;
import org.apache.logging.log4j.message.Message;

final class LogEventMapper {
public final class LogEventMapper {

/**
* Map the {@link LogEvent} data model onto the {@link LogBuilder}. Unmapped fields include:
Expand All @@ -34,12 +34,11 @@ final class LogEventMapper {
* <li>Mapped diagnostic context - {@link LogEvent#getContextData()}
* </ul>
*/
static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {
// message
Message message = logEvent.getMessage();
if (message != null) {
builder.setBody(message.getFormattedMessage());
}
public static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {
setBody(builder, logEvent.getMessage());
setSeverity(builder, logEvent.getLevel());
setThrowable(builder, logEvent.getThrown());
setContext(builder);

// time
Instant instant = logEvent.getInstant();
Expand All @@ -49,16 +48,22 @@ static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {
+ instant.getNanoOfMillisecond(),
TimeUnit.NANOSECONDS);
}
}

// level
Level level = logEvent.getLevel();
public static void setBody(LogBuilder builder, Message message) {
if (message != null) {
builder.setBody(message.getFormattedMessage());
}
}

public static void setSeverity(LogBuilder builder, Level level) {
if (level != null) {
builder.setSeverity(levelToSeverity(level));
builder.setSeverityText(logEvent.getLevel().name());
builder.setSeverityText(level.name());
}
}

// throwable
Throwable throwable = logEvent.getThrown();
public static void setThrowable(LogBuilder builder, Throwable throwable) {
if (throwable != null) {
AttributesBuilder attributes = Attributes.builder();

Expand All @@ -71,8 +76,9 @@ static void mapLogEvent(LogBuilder builder, LogEvent logEvent) {

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

// span context
public static void setContext(LogBuilder builder) {
builder.setContext(Context.current());
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
* SPDX-License-Identifier: Apache-2.0
*/

package io.opentelemetry.instrumentation.log4j.v2_16;
package io.opentelemetry.instrumentation.log4j.appender.v2_16;

import static org.assertj.core.api.AssertionsForInterfaceTypes.assertThat;

Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN"
packages="com.example.appender,io.opentelemetry.instrumentation.log4j.v2_16">
packages="com.example.appender,io.opentelemetry.instrumentation.log4j.appender.v2_16">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout
Expand Down
1 change: 1 addition & 0 deletions settings.gradle.kts
Original file line number Diff line number Diff line change
Expand Up @@ -271,6 +271,7 @@ include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2.7:ja
include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2.16:javaagent")
include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2.16:library-autoconfigure")
include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2-common:testing")
include(":instrumentation:log4j:log4j-appender-2.16:javaagent")
include(":instrumentation:log4j:log4j-appender-2.16:library")
include(":instrumentation:logback:logback-appender-1.0:javaagent")
include(":instrumentation:logback:logback-mdc-1.0:javaagent")
Expand Down

0 comments on commit 816514d

Please sign in to comment.