Bridge agent logs into application's slf4j logger (#7339)

Related discussion #7257
Resolves #3413
Resolves #5059
Resolves #6258
Resolves #7179

Adds a logging implementation that'll collect agent logs in memory until
slf4j is detected in the instrumented application; and when that happens
will dump all the logs into the application slf4j and log directly to
the application logger from that time on.

It's still in a POC state, unfortunately: while it works fine with an
app that uses & initializes slf4j directly, Spring Boot applications
actually reconfigure the logging implementation (e.g. logback) a while
after slf4j is loaded; which causes all the startup agent logs (debug
included) to be dumped with the default logback pattern.

Future work:
* ~~Make sure all logs produces by the agent are sent to loggers named
`io.opentelemetry...`
(https://github.com/open-telemetry/opentelemetry-java-instrumentation/pull/7446)~~
DONE
* Make this work on Spring Boot
* Documentation
* Smoke test?
This commit is contained in:
Mateusz Rzeszutek 2023-04-04 17:29:43 +02:00 committed by GitHub
parent 402635bb64
commit 04f2e3e9e5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
32 changed files with 1116 additions and 37 deletions

View File

@ -20,6 +20,7 @@ dependencies {
testImplementation(project(":testing-common"))
testImplementation("io.opentelemetry:opentelemetry-sdk-metrics")
testImplementation("io.opentelemetry:opentelemetry-sdk-testing")
testImplementation("org.junit-pioneer:junit-pioneer")
jmhImplementation(project(":instrumentation-api-semconv"))
}
@ -35,4 +36,10 @@ tasks {
isEnabled.set(false)
}
}
withType<Test>().configureEach {
// required on jdk17
jvmArgs("--add-opens=java.base/java.util=ALL-UNNAMED")
jvmArgs("-XX:+IgnoreUnrecognizedVMOptions")
}
}

View File

@ -19,6 +19,18 @@ public final class ConfigPropertiesUtil {
return strValue == null ? defaultValue : Boolean.parseBoolean(strValue);
}
public static int getInt(String propertyName, int defaultValue) {
String strValue = getString(propertyName);
if (strValue == null) {
return defaultValue;
}
try {
return Integer.parseInt(strValue);
} catch (NumberFormatException ignored) {
return defaultValue;
}
}
@Nullable
public static String getString(String propertyName) {
String value = System.getProperty(propertyName);

View File

@ -0,0 +1,75 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.instrumentation.api.internal;
import static org.assertj.core.api.Assertions.assertThat;
import org.junit.jupiter.api.Test;
import org.junitpioneer.jupiter.SetEnvironmentVariable;
import org.junitpioneer.jupiter.SetSystemProperty;
class ConfigPropertiesUtilTest {
@SetEnvironmentVariable(key = "TEST_PROPERTY_STRING", value = "env")
@SetSystemProperty(key = "test.property.string", value = "sys")
@Test
void getString_systemProperty() {
assertThat(ConfigPropertiesUtil.getString("test.property.string")).isEqualTo("sys");
}
@SetEnvironmentVariable(key = "TEST_PROPERTY_STRING", value = "env")
@Test
void getString_environmentVariable() {
assertThat(ConfigPropertiesUtil.getString("test.property.string")).isEqualTo("env");
}
@Test
void getString_none() {
assertThat(ConfigPropertiesUtil.getString("test.property.string")).isNull();
}
@SetEnvironmentVariable(key = "TEST_PROPERTY_INT", value = "12")
@SetSystemProperty(key = "test.property.int", value = "42")
@Test
void getInt_systemProperty() {
assertThat(ConfigPropertiesUtil.getInt("test.property.int", -1)).isEqualTo(42);
}
@SetEnvironmentVariable(key = "TEST_PROPERTY_INT", value = "12")
@Test
void getInt_environmentVariable() {
assertThat(ConfigPropertiesUtil.getInt("test.property.int", -1)).isEqualTo(12);
}
@Test
void getInt_none() {
assertThat(ConfigPropertiesUtil.getInt("test.property.int", -1)).isEqualTo(-1);
}
@SetSystemProperty(key = "test.property.int", value = "not a number")
@Test
void getInt_invalidNumber() {
assertThat(ConfigPropertiesUtil.getInt("test.property.int", -1)).isEqualTo(-1);
}
@SetEnvironmentVariable(key = "TEST_PROPERTY_BOOLEAN", value = "false")
@SetSystemProperty(key = "test.property.boolean", value = "true")
@Test
void getBoolean_systemProperty() {
assertThat(ConfigPropertiesUtil.getBoolean("test.property.boolean", false)).isTrue();
}
@SetEnvironmentVariable(key = "TEST_PROPERTY_BOOLEAN", value = "true")
@Test
void getBoolean_environmentVariable() {
assertThat(ConfigPropertiesUtil.getBoolean("test.property.boolean", false)).isTrue();
}
@Test
void getBoolean_none() {
assertThat(ConfigPropertiesUtil.getBoolean("test.property.boolean", false)).isFalse();
}
}

View File

@ -0,0 +1,7 @@
plugins {
id("otel.javaagent-bootstrap")
}
dependencies {
compileOnly(project(":javaagent-bootstrap"))
}

View File

@ -0,0 +1,35 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.bootstrap.logging;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import java.util.concurrent.atomic.AtomicReference;
public abstract class ApplicationLoggerBridge {
private static final AtomicReference<ApplicationLoggerBridge> applicationLoggerBridge =
new AtomicReference<>();
public static void set(ApplicationLoggerBridge bridge) {
if (!applicationLoggerBridge.compareAndSet(null, bridge)) {
throw new IllegalStateException(
"ApplicationLoggerBridge was already set earlier."
+ " This should never happen in a properly build javaagent, and it's most likely a result of an error in the javaagent build.");
}
}
public static void installApplicationLogger(InternalLogger.Factory applicationLoggerFactory) {
ApplicationLoggerBridge bridge = applicationLoggerBridge.get();
if (bridge == null) {
throw new IllegalStateException(
"ApplicationLoggerBridge#set() was not called before an attempt to install a bridge was made."
+ " This should never happen in a properly build javaagent, and it's most likely a result of an error in the javaagent build.");
}
bridge.install(applicationLoggerFactory);
}
protected abstract void install(InternalLogger.Factory applicationLoggerFactory);
}

View File

@ -0,0 +1,25 @@
plugins {
id("otel.javaagent-instrumentation")
}
muzzle {
pass {
group.set("org.slf4j")
module.set("slf4j-api")
versions.set("[1.4.0,)")
assertInverse.set(true)
}
}
dependencies {
bootstrap(project(":instrumentation:internal:internal-application-logger:bootstrap"))
compileOnly(project(":javaagent-bootstrap"))
compileOnly("org.slf4j:slf4j-api") {
version {
// 1.4.0 introduced the TRACE logging level
strictly("1.4.0")
}
}
}

View File

@ -0,0 +1,20 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.instrumentation.internal.logging;
import com.google.auto.service.AutoService;
import io.opentelemetry.javaagent.extension.ignore.IgnoredTypesBuilder;
import io.opentelemetry.javaagent.extension.ignore.IgnoredTypesConfigurer;
import io.opentelemetry.sdk.autoconfigure.spi.ConfigProperties;
@AutoService(IgnoredTypesConfigurer.class)
public final class ApplicationLoggingIgnoredTypesConfigurer implements IgnoredTypesConfigurer {
@Override
public void configure(IgnoredTypesBuilder builder, ConfigProperties config) {
builder.allowClass("org.slf4j.LoggerFactory");
}
}

View File

@ -0,0 +1,33 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.instrumentation.internal.logging;
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 io.opentelemetry.sdk.autoconfigure.spi.ConfigProperties;
import java.util.List;
@AutoService(InstrumentationModule.class)
public class ApplicationLoggingInstrumentationModule extends InstrumentationModule {
public ApplicationLoggingInstrumentationModule() {
super("internal-application-logging");
}
@Override
public boolean defaultEnabled(ConfigProperties config) {
// only enable this instrumentation if the application logger is enabled
return "application".equals(config.getString("otel.javaagent.logging"));
}
@Override
public List<TypeInstrumentation> typeInstrumentations() {
return singletonList(new LoggerFactoryInstrumentation());
}
}

View File

@ -0,0 +1,40 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.instrumentation.internal.logging;
import static net.bytebuddy.matcher.ElementMatchers.named;
import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
import net.bytebuddy.asm.Advice;
import net.bytebuddy.description.type.TypeDescription;
import net.bytebuddy.matcher.ElementMatcher;
public class LoggerFactoryInstrumentation implements TypeInstrumentation {
@Override
public ElementMatcher<TypeDescription> typeMatcher() {
return named("org.slf4j.LoggerFactory");
}
@Override
public void transform(TypeTransformer transformer) {
// once a call to getILoggerFactory() exits we can be certain that slf4j is properly initialized
transformer.applyAdviceToMethod(
named("getILoggerFactory").and(takesArguments(0)),
this.getClass().getName() + "$GetLoggerFactoryAdvice");
}
@SuppressWarnings("unused")
public static class GetLoggerFactoryAdvice {
@Advice.OnMethodExit(suppress = Throwable.class)
public static void onExit() {
Slf4jApplicationLoggerBridge.install();
}
}
}

View File

@ -0,0 +1,81 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.instrumentation.internal.logging;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerBridge;
import java.util.concurrent.atomic.AtomicBoolean;
import javax.annotation.Nullable;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public final class Slf4jApplicationLoggerBridge implements InternalLogger.Factory {
private static final AtomicBoolean installed = new AtomicBoolean();
public static void install() {
if (installed.compareAndSet(false, true)) {
ApplicationLoggerBridge.installApplicationLogger(new Slf4jApplicationLoggerBridge());
}
}
@Override
public InternalLogger create(String name) {
return new Slf4jApplicationLogger(name);
}
static final class Slf4jApplicationLogger implements InternalLogger {
private final Logger slf4jLogger;
Slf4jApplicationLogger(String name) {
this.slf4jLogger = LoggerFactory.getLogger(name);
}
@Override
public boolean isLoggable(Level level) {
switch (level) {
case ERROR:
return slf4jLogger.isErrorEnabled();
case WARN:
return slf4jLogger.isWarnEnabled();
case INFO:
return slf4jLogger.isInfoEnabled();
case DEBUG:
return slf4jLogger.isDebugEnabled();
case TRACE:
return slf4jLogger.isTraceEnabled();
}
return false; // unreachable
}
@Override
public void log(Level level, String message, @Nullable Throwable error) {
switch (level) {
case ERROR:
slf4jLogger.error(message, error);
break;
case WARN:
slf4jLogger.warn(message, error);
break;
case INFO:
slf4jLogger.info(message, error);
break;
case DEBUG:
slf4jLogger.debug(message, error);
break;
case TRACE:
slf4jLogger.trace(message, error);
break;
}
}
@Override
public String name() {
return slf4jLogger.getName();
}
}
}

View File

@ -5,36 +5,25 @@
package io.opentelemetry.javaagent.bootstrap;
import java.util.concurrent.atomic.AtomicReference;
import javax.annotation.Nullable;
public abstract class InternalLogger {
public interface InternalLogger {
private static final AtomicReference<Factory> loggerFactory =
new AtomicReference<>(NoopLoggerFactory.INSTANCE);
public static void initialize(Factory factory) {
if (!loggerFactory.compareAndSet(NoopLoggerFactory.INSTANCE, factory)) {
factory
.create(InternalLogger.class.getName())
.log(
Level.WARN,
"Developer error: logging system has already been initialized once",
null);
}
static void initialize(Factory factory) {
InternalLoggerFactoryHolder.initialize(factory);
}
static InternalLogger getLogger(String name) {
return loggerFactory.get().create(name);
return InternalLoggerFactoryHolder.get().create(name);
}
protected abstract boolean isLoggable(Level level);
boolean isLoggable(Level level);
protected abstract void log(Level level, String message, @Nullable Throwable error);
void log(Level level, String message, @Nullable Throwable error);
protected abstract String name();
String name();
public enum Level {
enum Level {
ERROR,
WARN,
INFO,
@ -43,7 +32,7 @@ public abstract class InternalLogger {
}
@FunctionalInterface
public interface Factory {
interface Factory {
InternalLogger create(String name);
}

View File

@ -0,0 +1,31 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.bootstrap;
import java.util.concurrent.atomic.AtomicReference;
final class InternalLoggerFactoryHolder {
private static final AtomicReference<InternalLogger.Factory> loggerFactory =
new AtomicReference<>(NoopLoggerFactory.INSTANCE);
static void initialize(InternalLogger.Factory factory) {
if (!loggerFactory.compareAndSet(NoopLoggerFactory.INSTANCE, factory)) {
factory
.create(InternalLogger.class.getName())
.log(
InternalLogger.Level.WARN,
"Developer error: logging system has already been initialized once",
null);
}
}
static InternalLogger.Factory get() {
return loggerFactory.get();
}
private InternalLoggerFactoryHolder() {}
}

View File

@ -18,7 +18,7 @@ final class NoopLoggerFactory implements InternalLogger.Factory {
return new NoopLogger(name);
}
private static final class NoopLogger extends InternalLogger {
private static final class NoopLogger implements InternalLogger {
private final String name;
@ -35,7 +35,7 @@ final class NoopLoggerFactory implements InternalLogger.Factory {
public void log(Level level, String message, @Nullable Throwable error) {}
@Override
protected String name() {
public String name() {
return name;
}
}

View File

@ -0,0 +1,25 @@
plugins {
id("otel.java-conventions")
id("otel.publish-conventions")
}
group = "io.opentelemetry.javaagent"
dependencies {
compileOnly(project(":instrumentation-api"))
compileOnly(project(":javaagent-bootstrap"))
compileOnly(project(":javaagent-tooling"))
compileOnly(project(":instrumentation:internal:internal-application-logger:bootstrap"))
testImplementation(project(":instrumentation-api"))
testImplementation(project(":javaagent-bootstrap"))
testImplementation(project(":javaagent-tooling"))
testImplementation(project(":instrumentation:internal:internal-application-logger:bootstrap"))
annotationProcessor("com.google.auto.service:auto-service")
compileOnly("com.google.auto.service:auto-service-annotations")
testCompileOnly("com.google.auto.service:auto-service-annotations")
compileOnly("com.google.auto.value:auto-value-annotations")
annotationProcessor("com.google.auto.value:auto-value")
}

View File

@ -0,0 +1,49 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import javax.annotation.Nullable;
final class ApplicationLogger implements InternalLogger {
private final InMemoryLogStore inMemoryLogStore;
private final String name;
private volatile InternalLogger actual;
ApplicationLogger(InMemoryLogStore inMemoryLogStore, String name) {
this.inMemoryLogStore = inMemoryLogStore;
this.name = name;
}
@Override
public boolean isLoggable(Level level) {
InternalLogger actual = this.actual;
if (actual == null) {
return true;
}
return actual.isLoggable(level);
}
@Override
public void log(Level level, String message, @Nullable Throwable error) {
InternalLogger actual = this.actual;
if (actual == null) {
inMemoryLogStore.write(InMemoryLog.create(name, level, message, error));
return;
}
actual.log(level, message, error);
}
@Override
public String name() {
return name;
}
void replaceByActualLogger(InternalLogger bridgedApplicationLogger) {
actual = bridgedApplicationLogger;
}
}

View File

@ -0,0 +1,77 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerBridge;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.atomic.AtomicBoolean;
final class ApplicationLoggerFactory extends ApplicationLoggerBridge
implements InternalLogger.Factory {
private final AtomicBoolean installed = new AtomicBoolean();
private volatile InternalLogger.Factory actual = null;
private final ConcurrentMap<String, ApplicationLogger> inMemoryLoggers =
new ConcurrentHashMap<>();
private final InMemoryLogStore inMemoryLogStore;
ApplicationLoggerFactory(InMemoryLogStore inMemoryLogStore) {
this.inMemoryLogStore = inMemoryLogStore;
}
@Override
protected void install(InternalLogger.Factory applicationLoggerFactory) {
// just use the first bridge that gets discovered and ignore the rest
if (!installed.compareAndSet(false, true)) {
applicationLoggerFactory
.create(ApplicationLoggerBridge.class.getName())
.log(
InternalLogger.Level.WARN,
"Multiple application logger implementations were provided."
+ " The javaagent will use the first bridge provided and ignore the following ones (this one).",
null);
return;
}
// flushing may cause additional classes to be loaded (e.g. slf4j loads logback, which we
// instrument), so we're doing this repeatedly to clear the in-memory store and preserve the
// log ordering
while (inMemoryLogStore.currentSize() > 0) {
inMemoryLogStore.flush(applicationLoggerFactory);
}
// actually install the application logger - from this point, everything will be logged
// directly through the application logging system
inMemoryLoggers
.values()
.forEach(
logger -> logger.replaceByActualLogger(applicationLoggerFactory.create(logger.name())));
this.actual = applicationLoggerFactory;
// if there are any leftover logs left in the memory store, flush them - this will cause some
// logs to go out of order, but at least we'll not lose any of them
if (inMemoryLogStore.currentSize() > 0) {
inMemoryLogStore.flush(applicationLoggerFactory);
}
// finally, free the memory
inMemoryLogStore.freeMemory();
inMemoryLoggers.clear();
}
@Override
public InternalLogger create(String name) {
InternalLogger.Factory bridgedLoggerFactory = this.actual;
// if the bridge was already installed skip the in-memory logger
if (bridgedLoggerFactory != null) {
return bridgedLoggerFactory.create(name);
}
return inMemoryLoggers.computeIfAbsent(name, n -> new ApplicationLogger(inMemoryLogStore, n));
}
}

View File

@ -0,0 +1,45 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import com.google.auto.service.AutoService;
import io.opentelemetry.instrumentation.api.internal.ConfigPropertiesUtil;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerBridge;
import io.opentelemetry.javaagent.tooling.LoggingCustomizer;
@AutoService(LoggingCustomizer.class)
public final class ApplicationLoggingCustomizer implements LoggingCustomizer {
@Override
public String name() {
return "application";
}
@Override
public void init() {
int limit =
ConfigPropertiesUtil.getInt(
"otel.javaagent.logging.application.logs-buffer-max-records", 2048);
InMemoryLogStore inMemoryLogStore = new InMemoryLogStore(limit);
ApplicationLoggerFactory loggerFactory = new ApplicationLoggerFactory(inMemoryLogStore);
// register a shutdown hook that'll dump the logs to stderr in case something goes wrong
Runtime.getRuntime().addShutdownHook(new Thread(() -> inMemoryLogStore.dump(System.err)));
ApplicationLoggerBridge.set(loggerFactory);
InternalLogger.initialize(loggerFactory);
}
@Override
public void onStartupSuccess() {}
@Override
@SuppressWarnings("SystemOut")
public void onStartupFailure(Throwable throwable) {
// most likely the application bridge wasn't initialized, let's just print
System.err.println("OpenTelemetry Javaagent failed to start");
throwable.printStackTrace();
}
}

View File

@ -0,0 +1,42 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import com.google.auto.value.AutoValue;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import java.io.PrintStream;
import javax.annotation.Nullable;
@AutoValue
abstract class InMemoryLog {
static InMemoryLog create(
String name, InternalLogger.Level level, String message, @Nullable Throwable error) {
return new AutoValue_InMemoryLog(name, level, message, error);
}
abstract String name();
abstract InternalLogger.Level level();
abstract String message();
@Nullable
abstract Throwable error();
void dump(PrintStream out) {
out.print("[otel.javaagent] ");
out.print(level());
out.print(" ");
out.print(name());
out.print(" - ");
out.println(message());
Throwable error = error();
if (error != null) {
error.printStackTrace(out);
}
}
}

View File

@ -0,0 +1,78 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import io.opentelemetry.instrumentation.api.internal.GuardedBy;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import java.io.PrintStream;
import java.util.ArrayList;
import java.util.List;
final class InMemoryLogStore {
private final Object lock = new Object();
@GuardedBy("lock")
private final ArrayList<InMemoryLog> inMemoryLogs = new ArrayList<>();
private final int limit;
InMemoryLogStore(int limit) {
this.limit = limit;
}
void write(InMemoryLog log) {
synchronized (lock) {
// just drop the log if hit the limit
if (limit >= 0 && inMemoryLogs.size() >= limit) {
return;
}
inMemoryLogs.add(log);
}
}
void flush(InternalLogger.Factory applicationLoggerFactory) {
List<InMemoryLog> copy;
synchronized (lock) {
copy = new ArrayList<>(inMemoryLogs);
inMemoryLogs.clear();
}
// calling the application logging system may cause additional classes to be loaded, and this
// will cause more logs to be added to this store - we need to work on a copy here to avoid a
// ConcurrentModificationException
for (InMemoryLog log : copy) {
applicationLoggerFactory.create(log.name()).log(log.level(), log.message(), log.error());
}
}
int currentSize() {
synchronized (lock) {
return inMemoryLogs.size();
}
}
void freeMemory() {
synchronized (lock) {
inMemoryLogs.clear();
inMemoryLogs.trimToSize();
}
}
void dump(PrintStream out) {
// make a copy to avoid ConcurrentModificationException in case some other thread writes a log
for (InMemoryLog log : copyLogs()) {
log.dump(out);
}
}
// visible for tests
List<InMemoryLog> copyLogs() {
synchronized (lock) {
return new ArrayList<>(inMemoryLogs);
}
}
}

View File

@ -0,0 +1,92 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.INFO;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.WARN;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.ArgumentMatchers.anyString;
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.ArgumentMatchers.isNull;
import static org.mockito.Mockito.never;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.when;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerBridge;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.mockito.Mock;
import org.mockito.junit.jupiter.MockitoExtension;
@ExtendWith(MockitoExtension.class)
class ApplicationLoggerFactoryTest {
@Mock InMemoryLogStore logStore;
@Mock InternalLogger.Factory applicationLoggerBridge;
@Mock InternalLogger applicationLogger;
ApplicationLoggerFactory underTest;
@BeforeEach
void setUp() {
underTest = new ApplicationLoggerFactory(logStore);
}
@Test
void shouldNotDuplicateLoggers() {
InternalLogger testLogger = underTest.create("test-logger");
InternalLogger anotherLogger1 = underTest.create("another-logger");
InternalLogger anotherLogger2 = underTest.create("another-logger");
assertThat(testLogger).isNotSameAs(anotherLogger1).isNotSameAs(anotherLogger2);
assertThat(anotherLogger1).isSameAs(anotherLogger2);
}
@Test
void shouldOnlyInstallTheFirstBridge() {
when(logStore.currentSize()).thenReturn(1, 0, 0);
when(applicationLoggerBridge.create(any())).thenReturn(applicationLogger);
underTest.install(applicationLoggerBridge);
verify(logStore, times(3)).currentSize();
verify(logStore).flush(applicationLoggerBridge);
verify(logStore).freeMemory();
underTest.install(applicationLoggerBridge);
// verify logged warning
verify(applicationLoggerBridge).create(ApplicationLoggerBridge.class.getName());
verify(applicationLogger).log(eq(WARN), anyString(), isNull());
verifyNoMoreInteractions(logStore);
}
@Test
void shouldReplaceLoggerAfterTheBridgeIsInstalled() {
InternalLogger beforeInstall = underTest.create("logger");
assertThat(beforeInstall).isInstanceOf(ApplicationLogger.class);
beforeInstall.log(INFO, "before", null);
verify(logStore).write(InMemoryLog.create("logger", INFO, "before", null));
when(applicationLoggerBridge.create("logger")).thenReturn(applicationLogger);
underTest.install(applicationLoggerBridge);
InternalLogger afterInstall = underTest.create("logger");
assertThat(afterInstall).isSameAs(applicationLogger);
beforeInstall.log(INFO, "after", null);
verify(applicationLogger).log(INFO, "after", null);
verify(logStore, never()).write(InMemoryLog.create("logger", INFO, "after", null));
}
}

View File

@ -0,0 +1,60 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.DEBUG;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.INFO;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.when;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.EnumSource;
import org.mockito.Mock;
import org.mockito.junit.jupiter.MockitoExtension;
@ExtendWith(MockitoExtension.class)
class ApplicationLoggerTest {
@Mock InMemoryLogStore logStore;
@Mock InternalLogger actualLogger;
@ParameterizedTest
@EnumSource(InternalLogger.Level.class)
void shouldCaptureAllLogLevelsInMemory(InternalLogger.Level level) {
ApplicationLogger underTest = new ApplicationLogger(logStore, "test");
assertThat(underTest.isLoggable(level)).isTrue();
}
@Test
void shouldStoreLogsInMemory() {
ApplicationLogger underTest = new ApplicationLogger(logStore, "test");
assertThat(underTest.name()).isEqualTo("test");
underTest.log(INFO, "a", null);
verify(logStore).write(InMemoryLog.create("test", INFO, "a", null));
}
@Test
void shouldReplaceTheLogger() {
ApplicationLogger underTest = new ApplicationLogger(logStore, "test");
underTest.replaceByActualLogger(actualLogger);
when(actualLogger.isLoggable(DEBUG)).thenReturn(false);
assertThat(underTest.isLoggable(DEBUG)).isFalse();
underTest.log(INFO, "a", null);
verify(actualLogger).log(INFO, "a", null);
verifyNoMoreInteractions(logStore);
}
}

View File

@ -0,0 +1,89 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import static org.assertj.core.api.Assertions.assertThat;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import io.opentelemetry.javaagent.bootstrap.InternalLogger.Level;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.Test;
class ConcurrentIntegrationTest {
ScheduledExecutorService threadPool = Executors.newScheduledThreadPool(4);
@AfterEach
void tearDown() {
threadPool.shutdownNow();
}
@Test
void shouldLogEverything() throws InterruptedException {
ApplicationLoggerFactory underTest = new ApplicationLoggerFactory(new InMemoryLogStore(-1));
AtomicInteger count = new AtomicInteger(0);
List<Integer> logMessages = new CopyOnWriteArrayList<>();
List<ScheduledFuture<?>> futures = new ArrayList<>();
for (int i = 0; i < 4; ++i) {
futures.add(
threadPool.scheduleAtFixedRate(
() ->
underTest
.create("test")
.log(Level.INFO, String.valueOf(count.incrementAndGet()), null),
0,
1,
TimeUnit.MILLISECONDS));
}
Thread.sleep(100);
underTest.install(name -> new TestLogger(name, logMessages));
Thread.sleep(100);
futures.forEach(f -> f.cancel(true));
assertThat(logMessages)
.as("Verify that the application logger bridge did not lose any messages")
.hasSize(count.get());
}
private static final class TestLogger implements InternalLogger {
private final String name;
private final List<Integer> logMessages;
private TestLogger(String name, List<Integer> logMessages) {
this.name = name;
this.logMessages = logMessages;
}
@Override
public boolean isLoggable(Level level) {
return true;
}
@Override
public void log(Level level, String message, Throwable error) {
logMessages.add(Integer.parseInt(message));
}
@Override
public String name() {
return name;
}
}
}

View File

@ -0,0 +1,91 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.INFO;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.when;
import io.opentelemetry.javaagent.bootstrap.InternalLogger;
import java.io.ByteArrayOutputStream;
import java.io.PrintStream;
import java.io.UnsupportedEncodingException;
import java.nio.charset.StandardCharsets;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.mockito.Mock;
import org.mockito.junit.jupiter.MockitoExtension;
@ExtendWith(MockitoExtension.class)
class InMemoryLogStoreTest {
@Mock InternalLogger.Factory applicationLoggerBridge;
@Mock InternalLogger applicationLogger;
ExecutorService anotherThread = Executors.newSingleThreadExecutor();
@AfterEach
void tearDown() {
anotherThread.shutdownNow();
}
@Test
void shouldWriteLog() {
InMemoryLogStore underTest = new InMemoryLogStore(42);
InMemoryLog log = InMemoryLog.create("test-logger", INFO, "a", null);
underTest.write(log);
assertThat(underTest.copyLogs()).containsExactly(log);
}
@Test
void shouldNotWriteLogsOverLimit() {
InMemoryLogStore underTest = new InMemoryLogStore(2);
InMemoryLog log = InMemoryLog.create("test-logger", INFO, "a", null);
underTest.write(log);
underTest.write(log);
underTest.write(log);
assertThat(underTest.copyLogs()).hasSize(2);
}
@Test
void shouldFlush() {
InMemoryLogStore underTest = new InMemoryLogStore(42);
InMemoryLog log = InMemoryLog.create("test-logger", INFO, "a", null);
underTest.write(log);
underTest.write(log);
assertThat(underTest.copyLogs()).hasSize(2);
when(applicationLoggerBridge.create("test-logger")).thenReturn(applicationLogger);
underTest.flush(applicationLoggerBridge);
verify(applicationLogger, times(2)).log(INFO, "a", null);
assertThat(underTest.copyLogs()).isEmpty();
}
@Test
void shouldDumpLogs() throws UnsupportedEncodingException {
InMemoryLogStore underTest = new InMemoryLogStore(42);
InMemoryLog log = InMemoryLog.create("test-logger", INFO, "a", null);
underTest.write(log);
underTest.write(log);
ByteArrayOutputStream out = new ByteArrayOutputStream();
underTest.dump(new PrintStream(out));
assertThat(out.toString(StandardCharsets.UTF_8.name())).hasLineCount(2);
}
}

View File

@ -0,0 +1,32 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.javaagent.logging.application;
import static io.opentelemetry.javaagent.bootstrap.InternalLogger.Level.INFO;
import static org.assertj.core.api.Assertions.assertThat;
import java.io.ByteArrayOutputStream;
import java.io.PrintStream;
import java.io.UnsupportedEncodingException;
import java.nio.charset.StandardCharsets;
import org.junit.jupiter.api.Test;
class InMemoryLogTest {
@Test
void testDump() throws UnsupportedEncodingException {
ByteArrayOutputStream out = new ByteArrayOutputStream();
InMemoryLog log = InMemoryLog.create("test-logger", INFO, "a", new RuntimeException("boom!"));
log.dump(new PrintStream(out));
assertThat(out.toString(StandardCharsets.UTF_8.name()))
.startsWith(
"[otel.javaagent] INFO test-logger - a"
+ System.lineSeparator()
+ "java.lang.RuntimeException: boom!");
}
}

View File

@ -10,7 +10,7 @@ import javax.annotation.Nullable;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
final class Slf4jSimpleLogger extends InternalLogger {
final class Slf4jSimpleLogger implements InternalLogger {
static Slf4jSimpleLogger create(String name) {
return new Slf4jSimpleLogger(name);
@ -23,17 +23,17 @@ final class Slf4jSimpleLogger extends InternalLogger {
}
@Override
protected boolean isLoggable(Level level) {
public boolean isLoggable(Level level) {
return logger.isEnabledForLevel(toSlf4jLevel(level));
}
@Override
protected void log(Level level, String message, @Nullable Throwable error) {
public void log(Level level, String message, @Nullable Throwable error) {
logger.makeLoggingEventBuilder(toSlf4jLevel(level)).setCause(error).log(message);
}
@Override
protected String name() {
public String name() {
return logger.getName();
}

View File

@ -25,6 +25,11 @@ public final class Slf4jSimpleLoggingCustomizer implements LoggingCustomizer {
"org.slf4j.simpleLogger.defaultLogLevel";
private static final String SIMPLE_LOGGER_PREFIX = "org.slf4j.simpleLogger.log.";
@Override
public String name() {
return "simple";
}
@Override
public void init() {
setSystemPropertyDefault(SIMPLE_LOGGER_SHOW_DATE_TIME_PROPERTY, "true");

View File

@ -5,6 +5,7 @@
package io.opentelemetry.javaagent.tooling;
import io.opentelemetry.instrumentation.api.internal.ConfigPropertiesUtil;
import io.opentelemetry.instrumentation.api.internal.cache.weaklockfree.WeakConcurrentMapCleaner;
import io.opentelemetry.javaagent.bootstrap.AgentInitializer;
import io.opentelemetry.javaagent.bootstrap.AgentStarter;
@ -13,7 +14,6 @@ import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.Instrumentation;
import java.lang.instrument.UnmodifiableClassException;
import java.security.ProtectionDomain;
import java.util.Iterator;
import java.util.ServiceLoader;
import org.objectweb.asm.ClassReader;
import org.objectweb.asm.ClassVisitor;
@ -63,13 +63,24 @@ public class AgentStarterImpl implements AgentStarter {
public void start() {
extensionClassLoader = createExtensionClassLoader(getClass().getClassLoader(), javaagentFile);
Iterator<LoggingCustomizer> loggingCustomizers =
ServiceLoader.load(LoggingCustomizer.class, extensionClassLoader).iterator();
LoggingCustomizer loggingCustomizer;
if (loggingCustomizers.hasNext()) {
loggingCustomizer = loggingCustomizers.next();
} else {
loggingCustomizer = NoopLoggingCustomizer.INSTANCE;
String loggerImplementationName = ConfigPropertiesUtil.getString("otel.javaagent.logging");
// default to the built-in stderr slf4j-simple logger
if (loggerImplementationName == null) {
loggerImplementationName = "simple";
}
LoggingCustomizer loggingCustomizer = null;
for (LoggingCustomizer customizer :
ServiceLoader.load(LoggingCustomizer.class, extensionClassLoader)) {
if (customizer.name().equalsIgnoreCase(loggerImplementationName)) {
loggingCustomizer = customizer;
break;
}
}
// unsupported logger implementation; defaulting to noop
if (loggingCustomizer == null) {
logUnrecognizedLoggerImplWarning(loggerImplementationName);
loggingCustomizer = new NoopLoggingCustomizer();
}
Throwable startupError = null;
@ -88,6 +99,14 @@ public class AgentStarterImpl implements AgentStarter {
}
}
@SuppressWarnings("SystemOut")
private static void logUnrecognizedLoggerImplWarning(String loggerImplementationName) {
System.err.println(
"Unrecognized value of 'otel.javaagent.logging': '"
+ loggerImplementationName
+ "'. The agent will use the no-op implementation.");
}
@Override
public ClassLoader getExtensionClassLoader() {
return extensionClassLoader;

View File

@ -11,6 +11,13 @@ import io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk;
// DefaultLoggingCustomizer
public interface LoggingCustomizer {
/**
* Returns name of the logger implementation. Will be matched against the value of the {@code
* otel.javavagent.logger} system property - in case it is the same, this {@link
* LoggingCustomizer} will be used to initialize the javaagent logging subsystem.
*/
String name();
// note that if this throws an exception, it will end up calling onStartupFailure, because
// otherwise that exception will bubble up to OpenTelemetryAgent where a distro cannot control the
// logging of it.

View File

@ -5,8 +5,15 @@
package io.opentelemetry.javaagent.tooling;
enum NoopLoggingCustomizer implements LoggingCustomizer {
INSTANCE;
import com.google.auto.service.AutoService;
@AutoService(LoggingCustomizer.class)
public final class NoopLoggingCustomizer implements LoggingCustomizer {
@Override
public String name() {
return "none";
}
@Override
public void init() {}

View File

@ -98,7 +98,7 @@ public class GlobalIgnoredTypesConfigurer implements IgnoredTypesConfigurer {
.allowClass("sun.rmi.transport")
.allowClass("sun.net.www.http.HttpClient");
builder.ignoreClass("org.slf4j.").allowClass("org.slf4j.MDC");
builder.ignoreClass("org.slf4j.");
builder
.ignoreClass("org.springframework.core.$Proxy")

View File

@ -63,6 +63,7 @@ dependencies {
baseJavaagentLibs(project(":javaagent-extension-api"))
baseJavaagentLibs(project(":javaagent-tooling"))
baseJavaagentLibs(project(":javaagent-internal-logging-application"))
baseJavaagentLibs(project(":javaagent-internal-logging-simple", configuration = "shadow"))
baseJavaagentLibs(project(":muzzle"))
baseJavaagentLibs(project(":instrumentation:opentelemetry-api:opentelemetry-api-1.0:javaagent"))
@ -70,6 +71,7 @@ dependencies {
baseJavaagentLibs(project(":instrumentation:opentelemetry-instrumentation-api:javaagent"))
baseJavaagentLibs(project(":instrumentation:opentelemetry-instrumentation-annotations-1.16:javaagent"))
baseJavaagentLibs(project(":instrumentation:executors:javaagent"))
baseJavaagentLibs(project(":instrumentation:internal:internal-application-logger:javaagent"))
baseJavaagentLibs(project(":instrumentation:internal:internal-class-loader:javaagent"))
baseJavaagentLibs(project(":instrumentation:internal:internal-eclipse-osgi-3.6:javaagent"))
baseJavaagentLibs(project(":instrumentation:internal:internal-lambda:javaagent"))
@ -83,6 +85,7 @@ dependencies {
// in case there are dependencies (accidentally) pulled in by instrumentation modules
// but I couldn't get that to work
licenseReportDependencies(project(":javaagent-tooling"))
licenseReportDependencies(project(":javaagent-internal-logging-application"))
licenseReportDependencies(project(":javaagent-internal-logging-simple"))
licenseReportDependencies(project(":javaagent-extension-api"))

View File

@ -99,6 +99,7 @@ include(":javaagent-bootstrap")
include(":javaagent-extension-api")
include(":javaagent-tooling")
include(":javaagent-tooling:javaagent-tooling-java9")
include(":javaagent-internal-logging-application")
include(":javaagent-internal-logging-simple")
include(":javaagent")
@ -183,6 +184,8 @@ hideFromDependabot(":instrumentation:cdi-testing")
hideFromDependabot(":instrumentation:graphql-java-12.0:javaagent")
hideFromDependabot(":instrumentation:graphql-java-12.0:library")
hideFromDependabot(":instrumentation:graphql-java-12.0:testing")
hideFromDependabot(":instrumentation:internal:internal-application-logger:bootstrap")
hideFromDependabot(":instrumentation:internal:internal-application-logger:javaagent")
hideFromDependabot(":instrumentation:internal:internal-class-loader:javaagent")
hideFromDependabot(":instrumentation:internal:internal-class-loader:javaagent-integration-tests")
hideFromDependabot(":instrumentation:internal:internal-eclipse-osgi-3.6:javaagent")