Skip to content

Commit

Permalink
ComponentInstallers should run after LogManager if a custom one is de…
Browse files Browse the repository at this point in the history 
…tected (open-telemetry#2592)

* ComponentInstallers should run after LogManager if a custom one is detected

* Limit to Java 8
  • Loading branch information
Mateusz Rzeszutek authored Mar 18, 2021
1 parent 8112593 commit 9fff4a3
Showing 1 changed file with 62 additions and 95 deletions.
157 changes: 62 additions & 95 deletions javaagent-tooling/src/main/java/io/opentelemetry/javaagent/tooling/AgentInstaller.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,8 @@

package io.opentelemetry.javaagent.tooling;

import static io.opentelemetry.javaagent.bootstrap.AgentInitializer.isJavaBefore9;
import static io.opentelemetry.javaagent.tooling.Utils.getResourceName;
import static io.opentelemetry.javaagent.tooling.bytebuddy.matcher.NameMatchers.namedOneOf;
import static io.opentelemetry.javaagent.tooling.matcher.GlobalIgnoresMatcher.globalIgnoresMatcher;
import static net.bytebuddy.matcher.ElementMatchers.any;
Expand All @@ -13,7 +15,6 @@

import io.opentelemetry.instrumentation.api.config.Config;
import io.opentelemetry.javaagent.bootstrap.AgentClassLoader;
import io.opentelemetry.javaagent.bootstrap.AgentInitializer;
import io.opentelemetry.javaagent.instrumentation.api.SafeServiceLoader;
import io.opentelemetry.javaagent.instrumentation.api.internal.BootstrapPackagePrefixesHolder;
import io.opentelemetry.javaagent.spi.BootstrapPackagesProvider;
Expand Down Expand Up @@ -53,6 +54,13 @@ public class AgentInstaller {
private static final String JAVAAGENT_ENABLED_CONFIG = "otel.javaagent.enabled";
private static final String EXCLUDED_CLASSES_CONFIG = "otel.javaagent.exclude-classes";

// This property may be set to force synchronous ComponentInstaller#afterByteBuddyAgent()
// execution: the condition for delaying the ComponentInstaller initialization is pretty broad
// and in case it covers too much javaagent users can file a bug, force sync execution by setting
// this property to true and continue using the javaagent
private static final String FORCE_SYNCHRONOUS_COMPONENT_INSTALLER_CONFIG =
"otel.javaagent.experimental.force-synchronous-component-installers";

// We set this system property when running the agent with unit tests to allow verifying that we
// don't ignore libraries that we actually attempt to instrument. It means either the list is
// wrong or a type matcher is.
Expand Down Expand Up @@ -171,28 +179,30 @@ private static void installComponentsBeforeByteBuddy(

private static void installComponentsAfterByteBuddy(
Iterable<ComponentInstaller> componentInstallers, Config config) {
/*
* java.util.logging.LogManager maintains a final static LogManager, which is created during class initialization.
*
* JMXFetch uses jre bootstrap classes which touch this class. This means applications which require a custom log
* manager may not have a chance to set the global log manager if jmxfetch runs first. JMXFetch will incorrectly
* set the global log manager in cases where the app sets the log manager system property or when the log manager
* class is not on the system classpath.
*
* Our solution is to delay the initialization of jmxfetch when we detect a custom log manager being used.
*
* Once we see the LogManager class loading, it's safe to start jmxfetch because the application is already setting
* the global log manager and jmxfetch won't be able to touch it due to classloader locking.
*/

/*
* Similar thing happens with AgentTracer on (at least) zulu-8 because it uses OkHttp which indirectly loads JFR
* events which in turn loads LogManager. This is not a problem on newer JDKs because there JFR uses different
* logging facility.
*/
boolean appUsingCustomLogManager = isAppUsingCustomLogManager();
if (isJavaBefore9WithJfr() && appUsingCustomLogManager) {
log.debug("Custom logger detected. Delaying Agent Tracer initialization.");
// java.util.logging.LogManager maintains a final static LogManager, which is created during
// class initialization. Some ComponentInstaller implementations may use JRE bootstrap classes
// which touch this class (e.g. JFR classes or some MBeans).
// It is worth noting that starting from Java 9 (JEP 264) Java platform classes no longer use
// JUL directly, but instead they use a new System.Logger interface, so the LogManager issue
// applies mainly to Java 8.
// This means applications which require a custom LogManager may not have a chance to set the
// global LogManager if one of those ComponentInstallers runs first: it will incorrectly
// set the global LogManager to the default JVM one in cases where the instrumented application
// sets the LogManager system property or when the custom LogManager class is not on the system
// classpath.
// Our solution is to delay the initialization of ComponentInstallers when we detect a custom
// log manager being used.
// Once we see the LogManager class loading, it's safe to run
// ComponentInstaller#afterByteBuddyAgent() because the application is already setting the
// global LogManager and ComponentInstaller won't be able to touch it due to classloader
// locking.
boolean shouldForceSynchronousComponentInstallerCalls =
Config.get().getBooleanProperty(FORCE_SYNCHRONOUS_COMPONENT_INSTALLER_CONFIG, false);
if (!shouldForceSynchronousComponentInstallerCalls
&& isJavaBefore9()
&& isAppUsingCustomLogManager()) {
log.debug(
"Custom JUL LogManager detected: delaying ComponentInstaller#afterByteBuddyAgent() calls");
registerClassLoadCallback(
"java.util.logging.LogManager",
new InstallComponentAfterByteBuddyCallback(config, componentInstallers));
Expand Down Expand Up @@ -390,59 +400,38 @@ public static void registerClassLoadCallback(String className, Runnable callback
}
}

protected static class InstallComponentAfterByteBuddyCallback extends ClassLoadCallBack {

private static class InstallComponentAfterByteBuddyCallback implements Runnable {
private final Iterable<ComponentInstaller> componentInstallers;
private final Config config;

protected InstallComponentAfterByteBuddyCallback(
private InstallComponentAfterByteBuddyCallback(
Config config, Iterable<ComponentInstaller> componentInstallers) {
this.componentInstallers = componentInstallers;
this.config = config;
}

@Override
public String getName() {
return componentInstallers.getClass().getName();
}

@Override
public void execute() {
for (ComponentInstaller componentInstaller : componentInstallers) {
componentInstaller.afterByteBuddyAgent(config);
}
}
}

protected abstract static class ClassLoadCallBack implements Runnable {

@Override
public void run() {
/*
* This callback is called from within bytecode transformer. This can be a problem if callback tries
* to load classes being transformed. To avoid this we start a thread here that calls the callback.
* This seems to resolve this problem.
*/
Thread thread =
new Thread(
new Runnable() {
@Override
public void run() {
try {
execute();
} catch (Exception e) {
log.error("Failed to run class loader callback {}", getName(), e);
}
}
});
thread.setName("agent-startup-" + getName());
Thread thread = new Thread(this::runComponentInstallers);
thread.setName("agent-component-installers");
thread.setDaemon(true);
thread.start();
}

public abstract String getName();

public abstract void execute();
private void runComponentInstallers() {
for (ComponentInstaller componentInstaller : componentInstallers) {
try {
componentInstaller.afterByteBuddyAgent(config);
} catch (Exception e) {
log.error("Failed to execute {}", componentInstaller.getClass().getName(), e);
}
}
}
}

private static class ClassLoadListener implements AgentBuilder.Listener {
Expand Down Expand Up @@ -512,63 +501,41 @@ private static boolean isIgnored(Class<?> c) {
}
}

/**
* Search for java or agent-tracer sysprops which indicate that a custom log manager will be used.
* Also search for any app classes known to set a custom log manager.
*
* @return true if we detect a custom log manager being used.
*/
/** Detect if the instrumented application is using a custom JUL LogManager. */
private static boolean isAppUsingCustomLogManager() {
String tracerCustomLogManSysprop = "otel.app.customlogmanager";
String customLogManagerProp = System.getProperty(tracerCustomLogManSysprop);
String customLogManagerEnv =
System.getenv(tracerCustomLogManSysprop.replace('.', '_').toUpperCase());

if (customLogManagerProp != null || customLogManagerEnv != null) {
log.debug("Prop - customlogmanager: " + customLogManagerProp);
log.debug("Env - customlogmanager: " + customLogManagerEnv);
// Allow setting to skip these automatic checks:
return Boolean.parseBoolean(customLogManagerProp)
|| Boolean.parseBoolean(customLogManagerEnv);
}

String jbossHome = System.getenv("JBOSS_HOME");
if (jbossHome != null) {
log.debug("Env - jboss: " + jbossHome);
log.debug("Found JBoss: {}; assuming app is using custom LogManager", jbossHome);
// JBoss/Wildfly is known to set a custom log manager after startup.
// Originally we were checking for the presence of a jboss class,
// but it seems some non-jboss applications have jboss classes on the classpath.
// This would cause jmxfetch initialization to be delayed indefinitely.
// This would cause ComponentInstaller initialization to be delayed indefinitely.
// Checking for an environment variable required by jboss instead.
return true;
}

String logManagerProp = System.getProperty("java.util.logging.manager");
if (logManagerProp != null) {
String customLogManager = System.getProperty("java.util.logging.manager");
if (customLogManager != null) {
log.debug(
"Detected custom LogManager configuration: java.util.logging.manager={}",
customLogManager);
boolean onSysClasspath =
ClassLoader.getSystemResource(logManagerProp.replaceAll("\\.", "/") + ".class") != null;
log.debug("Prop - logging.manager: " + logManagerProp);
log.debug("logging.manager on system classpath: " + onSysClasspath);
ClassLoader.getSystemResource(getResourceName(customLogManager)) != null;
log.debug(
"Class {} is on system classpath: {}delaying ComponentInstaller#afterByteBuddyAgent()",
customLogManager,
onSysClasspath ? "not " : "");
// Some applications set java.util.logging.manager but never actually initialize the logger.
// Check to see if the configured manager is on the system classpath.
// If so, it should be safe to initialize jmxfetch which will setup the log manager.
// If so, it should be safe to initialize ComponentInstaller which will setup the log manager:
// LogManager tries to load the implementation first using system CL, then falls back to
// current context CL
return !onSysClasspath;
}

return false;
}

private static boolean isJavaBefore9WithJfr() {
if (!AgentInitializer.isJavaBefore9()) {
return false;
}
// FIXME: this is quite a hack because there maybe jfr classes on classpath somehow that have
// nothing to do with JDK but this should be safe because only thing this does is to delay
// tracer install
String jfrClassResourceName = "jdk.jfr.Recording".replace('.', '/') + ".class";
return Thread.currentThread().getContextClassLoader().getResource(jfrClassResourceName) != null;
}

private static void logVersionInfo() {
VersionLogger.logAllVersions();
log.debug(
Expand Down

0 comments on commit 9fff4a3

Please sign in to comment.