Skip to content

feat: add DEBUG-level logs for SPI extension loading in ExtensionLoader #16231

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.

Sign up for GitHub

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

Open
uuuyuqi wants to merge 14 commits into
base: 3.3
Choose a base branch
from
+238 −12
Open

feat: add DEBUG-level logs for SPI extension loading in ExtensionLoader #16231

Show file tree
Hide file tree
Changes from 9 commits
Commits
Show all changes
14 commits
Select commit Hold shift + click to select a range
fb8aa51
feat: add debug logs for SPI extension loading in ExtensionLoader
uuuyuqi Apr 13, 2026
d662f03
Merge branch '3.3' into extensionloader-log
zrlw Apr 26, 2026
86e4be4
Optimize logging in ExtensionLoader for debug mode
zrlw Apr 27, 2026
6c0e7f8
Add debug logging for wrapper class processing
zrlw Apr 27, 2026
813d269
Refactor ExtensionLoaderTest by cleaning imports
zrlw Apr 27, 2026
ada8706
Add Log4j imports to ExtensionLoaderTest
zrlw Apr 27, 2026
bb02b48
Add preLoggerConfig parameter to LogCollector
zrlw Apr 27, 2026
f559f66
Optimize debug logging checks in ExtensionLoader
zrlw Apr 27, 2026
d7efe33
Fix logger configuration retrieval in tests
zrlw Apr 27, 2026
b065dbe
Update dubbo-common/src/main/java/org/apache/dubbo/common/extension/E…
zrlw Apr 27, 2026
17dccac
Add getCurrentLoggerAdapter method
zrlw Apr 27, 2026
bd73870
Add logging support for extension creation tests
zrlw Apr 27, 2026
317b0cf
Fix Javadoc formatting in getCurrentLoggerAdapter
zrlw Apr 27, 2026
b9138f3
Remove duplicate import of 'Prioritized'
zrlw Apr 27, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
108 changes: 97 additions & 11 deletions dubbo-common/src/main/java/org/apache/dubbo/common/extension/ExtensionLoader.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -771,6 +771,7 @@ private IllegalStateException findException(String name) {

@SuppressWarnings("unchecked")
private T createExtension(String name, boolean wrap) {
final boolean debugEnabled = logger.isDebugEnabled();
Class<?> clazz = getExtensionClasses().get(name);
if (clazz == null || unacceptableExceptions.contains(name)) {
throw findException(name);
Expand All @@ -785,6 +786,7 @@ private T createExtension(String name, boolean wrap) {
instance = postProcessAfterInitialization(instance, name);
}

List<Class<?>> appliedWrapperClasses = Collections.emptyList();
if (wrap) {
List<Class<?>> wrapperClassesList = new ArrayList<>();
if (cachedWrapperClasses != null) {
Expand All @@ -794,13 +796,19 @@ private T createExtension(String name, boolean wrap) {
}

if (CollectionUtils.isNotEmpty(wrapperClassesList)) {
if (debugEnabled) {
appliedWrapperClasses = new ArrayList<>(wrapperClassesList.size());
}
for (Class<?> wrapperClass : wrapperClassesList) {
Wrapper wrapper = wrapperClass.getAnnotation(Wrapper.class);
boolean match = (wrapper == null)
|| ((ArrayUtils.isEmpty(wrapper.matches())
|| ArrayUtils.contains(wrapper.matches(), name))
&& !ArrayUtils.contains(wrapper.mismatches(), name));
if (match) {
if (debugEnabled) {
appliedWrapperClasses.add(wrapperClass);
}
instance = (T) wrapperClass.getConstructor(type).newInstance(instance);
instance = postProcessBeforeInitialization(instance, name);
injectExtension(instance);
Expand All @@ -813,6 +821,9 @@ private T createExtension(String name, boolean wrap) {
// Warning: After an instance of Lifecycle is wrapped by cachedWrapperClasses, it may not still be Lifecycle
// instance, this application may not invoke the lifecycle.initialize hook.
initExtension(instance);
if (debugEnabled) {
logExtensionInstanceLoaded(name, instance, wrap, appliedWrapperClasses);
}
return instance;
} catch (Throwable t) {
throw new IllegalStateException(
Expand All @@ -822,6 +833,17 @@ private T createExtension(String name, boolean wrap) {
}
}

private void logExtensionInstanceLoaded(String name, T instance, boolean wrap, List<Class<?>> wrapperClasses) {
logger.debug(
"Loaded extension instance, type={}, scopeModel={}, name={}, instanceClass={}, wrap={}, wrapperClasses={}",
type.getName(),
scopeModel,
name,
instance.getClass().getName(),
wrap,
wrapperClasses.stream().map(Class::getName).collect(Collectors.toList()));
}

private Object createExtensionInstance(Class<?> type) throws ReflectiveOperationException {
return instantiationStrategy.instantiate(type);
}
Expand Down Expand Up @@ -985,9 +1007,20 @@ private Map<String, Class<?>> getExtensionClasses() {
*/
@SuppressWarnings("deprecation")
private Map<String, Class<?>> loadExtensionClasses() throws InterruptedException {
final boolean debugEnabled = logger.isDebugEnabled();
checkDestroyed();
cacheDefaultExtensionName();

long startNanos = -1;
if (debugEnabled) {
startNanos = System.nanoTime();
logger.debug(
"Start loading extension classes, type={}, scopeModel={}, defaultName={}",
type.getName(),
scopeModel,
cachedDefaultName);
}

Map<String, Class<?>> extensionClasses = new HashMap<>();

for (LoadingStrategy strategy : strategies) {
Expand All @@ -999,6 +1032,22 @@ private Map<String, Class<?>> loadExtensionClasses() throws InterruptedException
}
}

if (debugEnabled) {
Long costMillis = (System.nanoTime() - startNanos) / 1_000_000L;
Copy link
Copy Markdown
Author

@uuuyuqi uuuyuqi Apr 27, 2026

Choose a reason for hiding this comment

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

At this point, startNanos might be null, for example, if the application dynamically modifies the log level at runtime. This is quite common in online troubleshooting scenarios. To be on the safe side, it's probably best to assign an initial value of null or -1.

Copy link
Copy Markdown
Contributor

@zrlw zrlw Apr 27, 2026

Choose a reason for hiding this comment

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

Capturing boolean debug = logger.isDebugEnabled(); at the beginning of methods and only computing/using timing when debug is true.

Comment thread
zrlw marked this conversation as resolved.
Outdated
List<String> wrapperClassNames = cachedWrapperClasses == null
? Collections.emptyList()
: cachedWrapperClasses.stream().map(Class::getName).collect(Collectors.toList());
logger.debug(
"Finished loading extension classes, type={}, scopeModel={}, count={}, adaptiveClass={}, wrapperClasses={}, names={}, costInMillis={}",
type.getName(),
scopeModel,
extensionClasses.size(),
cachedAdaptiveClass == null ? null : cachedAdaptiveClass.getName(),
wrapperClassNames,
new TreeSet<>(extensionClasses.keySet()),
costMillis);
}

return extensionClasses;
}

Expand Down Expand Up @@ -1270,22 +1319,38 @@ private void loadClass(
Class<?> clazz,
String name,
boolean overridden) {
final boolean debugEnabled = logger.isDebugEnabled();
if (!type.isAssignableFrom(clazz)) {
throw new IllegalStateException(
"Error occurred when loading extension class (interface: " + type + ", class line: "
+ clazz.getName() + "), class " + clazz.getName() + " is not subtype of interface.");
}

boolean isActive = loadClassIfActive(classLoader, clazz);
List<String> missingOnClass = findMissingOnClass(classLoader, clazz);

if (!isActive) {
if (missingOnClass != null && !missingOnClass.isEmpty()) {
if (debugEnabled) {
logger.debug(
"Skip inactive extension class, type={}, scopeModel={}, class={}, resourceURL={}, missingOnClass={}",
type.getName(),
scopeModel,
clazz.getName(),
resourceURL,
missingOnClass);
}
return;
}

if (clazz.isAnnotationPresent(Adaptive.class)) {
cacheAdaptiveClass(clazz, overridden);
if (debugEnabled) {
logLoadedExtensionClass("adaptive", clazz, null, resourceURL, overridden);
}
} else if (isWrapperClass(clazz)) {
cacheWrapperClass(clazz);
if (debugEnabled) {
logLoadedExtensionClass("wrapper", clazz, null, resourceURL, overridden);
}
} else {
if (StringUtils.isEmpty(name)) {
name = findAnnotationName(clazz);
Expand All @@ -1302,15 +1367,31 @@ private void loadClass(
cacheName(clazz, n);
saveInExtensionClass(extensionClasses, clazz, n, overridden);
}
if (debugEnabled) {
logLoadedExtensionClass("extension", clazz, names, resourceURL, overridden);
}
}
}
}

private boolean loadClassIfActive(ClassLoader classLoader, Class<?> clazz) {
private void logLoadedExtensionClass(
String kind, Class<?> clazz, String[] names, java.net.URL resourceURL, boolean overridden) {
logger.debug(
"Loaded SPI {} class, type={}, scopeModel={}, names={}, class={}, resourceURL={}, overridden={}",
kind,
type.getName(),
scopeModel,
names != null ? Arrays.asList(names) : Collections.emptyList(),
clazz.getName(),
resourceURL,
overridden);
}

private List<String> findMissingOnClass(ClassLoader classLoader, Class<?> clazz) {
Activate activate = clazz.getAnnotation(Activate.class);

if (activate == null) {
return true;
return null;
}
String[] onClass = null;

Expand All @@ -1322,14 +1403,19 @@ private boolean loadClassIfActive(ClassLoader classLoader, Class<?> clazz) {
onClass = Dubbo2ActivateUtils.getOnClass(activate);
}

boolean isActive = true;

if (null != onClass && onClass.length > 0) {
isActive = Arrays.stream(onClass)
.filter(StringUtils::isNotBlank)
.allMatch(className -> ClassUtils.isPresent(className, classLoader));
if (onClass == null || onClass.length == 0) {
return null;
}
List<String> missing = null;
for (String className : onClass) {
if (StringUtils.isNotBlank(className) && !ClassUtils.isPresent(className, classLoader)) {
if (missing == null) {
missing = new ArrayList<>(2);
}
missing.add(className);
}
}
return isActive;
return missing;
}

/**
Expand Down
118 changes: 117 additions & 1 deletion dubbo-common/src/test/java/org/apache/dubbo/common/extension/ExtensionLoaderTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,12 +70,20 @@
import org.apache.dubbo.common.lang.Prioritized;
import org.apache.dubbo.common.url.component.ServiceConfigURL;
import org.apache.dubbo.rpc.model.ApplicationModel;
import org.apache.dubbo.rpc.model.FrameworkModel;

import java.util.Collections;
import java.util.HashSet;
import java.util.List;
import java.util.Set;

import java.util.concurrent.CopyOnWriteArrayList;

import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.LoggerConfig;
import org.apache.logging.log4j.core.layout.PatternLayout;
import org.junit.jupiter.api.Assertions;
import org.junit.jupiter.api.Test;

Expand Down Expand Up @@ -192,6 +200,23 @@ void test_getExtension_WithWrapper() {
assertEquals(echoCount2 + 1, Ext6Wrapper2.echoCount.get());
}

@Test
void test_getExtension_logsDebugWhenExtensionCreated() {
try (ExtensionLoaderTestContext<WrappedExt> testContext = createExtensionLoaderTestContext(WrappedExt.class);
LogCollector logCollector = LogCollector.attach(ExtensionLoader.class)) {
WrappedExt impl1 = testContext.extensionLoader.getExtension("impl1");
Copy link

Copilot AI Apr 27, 2026

Choose a reason for hiding this comment

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

This test’s LogCollector only captures Log4j2 output, but ExtensionLoader logs through Dubbo’s LoggerFactory adapter, which is mutable global state and is set to non-log4j2 in other tests (e.g., LoggerFactoryTest, FailsafeErrorTypeAwareLoggerTest). That can make this test order-dependent/flaky because the DEBUG line may never reach Log4j2. Consider setting the logger adapter to log4j2 for the duration of this test (and restoring the previous adapter in close()/finally) before asserting on captured Log4j2 events.

Copilot uses AI. Check for mistakes.

assertNotNull(impl1);
assertTrue(logCollector.contains("Loaded extension instance, type=" + WrappedExt.class.getName()));
assertTrue(logCollector.contains("name=impl1"));
assertTrue(logCollector.contains("instanceClass=" + Ext6Wrapper1.class.getName())
|| logCollector.contains("instanceClass=" + Ext6Wrapper2.class.getName()));
assertTrue(logCollector.contains("wrapperClasses=["));
assertTrue(logCollector.contains(Ext6Wrapper1.class.getName()));
assertTrue(logCollector.contains(Ext6Wrapper2.class.getName()));
Comment thread
uuuyuqi marked this conversation as resolved.
Outdated
}
}

@Test
void test_getExtension_withWrapperAnnotation() {
WrappedExt impl3 = getExtensionLoader(WrappedExt.class).getExtension("impl3");
Expand Down Expand Up @@ -882,4 +907,95 @@ public int getPriority() {
return MAX_PRIORITY;
}
}

private <T> ExtensionLoaderTestContext<T> createExtensionLoaderTestContext(Class<T> type) {
FrameworkModel frameworkModel = new FrameworkModel();
ApplicationModel applicationModel = frameworkModel.newApplication();
return new ExtensionLoaderTestContext<>(
frameworkModel, applicationModel.getExtensionDirector().getExtensionLoader(type));
}

private static final class ExtensionLoaderTestContext<T> implements AutoCloseable {
private final FrameworkModel frameworkModel;
private final ExtensionLoader<T> extensionLoader;

private ExtensionLoaderTestContext(FrameworkModel frameworkModel, ExtensionLoader<T> extensionLoader) {
this.frameworkModel = frameworkModel;
this.extensionLoader = extensionLoader;
}

@Override
public void close() {
frameworkModel.destroy();
}
}

private static final class LogCollector implements AutoCloseable {
private final LoggerContext context;
private final Configuration configuration;
private final String loggerName;
private final LoggerConfig loggerConfig;
private final TestAppender appender;
private final LoggerConfig preLoggerConfig;

private LogCollector(
LoggerContext context,
Configuration configuration,
String loggerName,
LoggerConfig loggerConfig,
TestAppender appender,
LoggerConfig preLoggerConfig) {
this.context = context;
this.configuration = configuration;
this.loggerName = loggerName;
this.loggerConfig = loggerConfig;
this.appender = appender;
this.preLoggerConfig = preLoggerConfig;
}

static LogCollector attach(Class<?> loggerType) {
LoggerContext context = LoggerContext.getContext(false);
Configuration configuration = context.getConfiguration();
String loggerName = loggerType.getName();
TestAppender appender = new TestAppender("test-appender-" + loggerType.getSimpleName());
appender.start();
configuration.addAppender(appender);

LoggerConfig preLoggerConfig = configuration.getLoggers().get(loggerName);
LoggerConfig loggerConfig = new LoggerConfig(loggerName, org.apache.logging.log4j.Level.DEBUG, false);
loggerConfig.addAppender(appender, org.apache.logging.log4j.Level.DEBUG, null);
configuration.addLogger(loggerName, loggerConfig);
context.updateLoggers();
return new LogCollector(context, configuration, loggerName, loggerConfig, appender, preLoggerConfig);
}

boolean contains(String expected) {
return appender.messages.stream().anyMatch(message -> message.contains(expected));
}

@Override
public void close() {
loggerConfig.removeAppender(appender.getName());
configuration.removeLogger(loggerName);
appender.stop();
configuration.getAppenders().remove(appender.getName());
if (preLoggerConfig != null) {
configuration.addLogger(loggerName, preLoggerConfig);
}
context.updateLoggers();
}
}

private static final class TestAppender extends AbstractAppender {
private final List<String> messages = new CopyOnWriteArrayList<>();

private TestAppender(String name) {
super(name, null, PatternLayout.newBuilder().withPattern("%m").build(), false, null);
}

@Override
public void append(LogEvent event) {
messages.add(event.toImmutable().getMessage().getFormattedMessage());
}
}
}
Loading