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.

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

Jump to bottom

Dubbo use diferent behavior when log's level greater than info #2784

Closed
2 tasks done
chutian52 opened this issue Nov 13, 2018 · 4 comments
Closed
2 tasks done

Dubbo use diferent behavior when log's level greater than info #2784

chutian52 opened this issue Nov 13, 2018 · 4 comments

Comments

@chutian52
Copy link

chutian52 commented Nov 13, 2018 •
edited
Loading

  • I have searched the issues of this repository and believe that this is not a duplicate.
  • I have checked the FAQ of this repository and believe that this is not a duplicate.

Environment

  • Dubbo version: xxx
  • Operating System version: xxx
  • Java version: xxx

Steps to reproduce this issue

  1. First, create an interface.
public interface DemoService {

    String sayHello(String name);
}
  1. Create a controller
@RestController
public class DemoController {

    @Reference(version = "1.0.0")
    private DemoService demoService;

    @RequestMapping("/{name}")
    public String say(@PathVariable("name") String name){
        return demoService.sayHello(name);
    }
}
  1. Create a config class
@Configuration
public class DubboConfig {

    @Bean(ReferenceAnnotationBeanPostProcessor.BEAN_NAME)
    public ReferenceAnnotationBeanPostProcessor referenceAnnotationBeanPostProcessor(){
        return new ReferenceAnnotationBeanPostProcessor();
    }


    @ConditionalOnMissingBean
    @Bean
    public ApplicationConfig applicationConfig(){
        ApplicationConfig applicationConfig = new ApplicationConfig("dubbo-consumer-test");
        applicationConfig.setId("dubbo-consumer-test");
        applicationConfig.setDefault(true);
        return applicationConfig;
    }

    @ConditionalOnMissingBean
    @Bean
    public ProtocolConfig protocolConfig(){
        ProtocolConfig protocolConfig = new ProtocolConfig("dubbo");
        protocolConfig.setId("dubbo");
        protocolConfig.setClient("netty4");
        protocolConfig.setServer("netty4");
        protocolConfig.setDefault(true);
        return protocolConfig;
    }

    @ConditionalOnMissingBean
    @Bean
    public RegistryConfig registryConfig(){
        RegistryConfig registryConfig = new RegistryConfig("localhost:2181");
        registryConfig.setId("zookeeper");
        registryConfig.setDefault(true);
        registryConfig.setProtocol("zookeeper");
        return registryConfig;
    }
}
  1. Create a boot class
@SpringBootApplication
public class Application {

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }
}
  1. Invoke rest
$  curl -X GET -i 'http://localhost:8080/world'

throws exception like this(currently log's level is debug)

{"timestamp":1542107448435,"status":500,"error":"Internal Server Error","exception":"java.lang.NullPointerException","message":"No message available","path":"/world"}

starting log

2018-11-13 19:15:00.578 [main] WARN  c.a.d.c.AbstractConfig -  [DUBBO] null, dubbo version: 2.6.1, current host: 192.168.99.1
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_181]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_181]
	at com.alibaba.dubbo.config.AbstractConfig.toString(AbstractConfig.java:473) [dubbo-2.6.1.jar:2.6.1]
	at java.lang.String.valueOf(String.java:2994) [?:1.8.0_181]
	at java.lang.StringBuilder.append(StringBuilder.java:131) [?:1.8.0_181]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.AbstractAnnotationConfigBeanBuilder.build(AbstractAnnotationConfigBeanBuilder.java:75) [dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.buildReferenceBean(ReferenceAnnotationBeanPostProcessor.java:345) [dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.access$100(ReferenceAnnotationBeanPostProcessor.java:61) [dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor$ReferenceFieldElement.inject(ReferenceAnnotationBeanPostProcessor.java:323) [dubbo-2.6.1.jar:2.6.1]
	at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:88) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.postProcessPropertyValues(ReferenceAnnotationBeanPostProcessor.java:88) [dubbo-2.6.1.jar:2.6.1]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1264) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761) [spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:866) [spring-context-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:542) [spring-context-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:122) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:737) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:370) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1162) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1151) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at com.fft.dubbo.consumer.Application.main(Application.java:10) [classes/:?]
Caused by: java.lang.IllegalStateException: Failed to check the status of the service com.fft.dubbo.consumer.service.DemoService. No provider available for the service com.fft.dubbo.consumer.service.DemoService:1.0.0 from the url zookeeper://localhost:2181/com.alibaba.dubbo.registry.RegistryService?application=dubbo-consumer-test&default=true&dubbo=2.6.1&interface=com.fft.dubbo.consumer.service.DemoService&methods=sayHello&pid=11737&register.ip=192.168.99.1&revision=1.0.0&side=consumer&timestamp=1542107700378&version=1.0.0 to the consumer 192.168.99.1 use dubbo version 2.6.1
	at com.alibaba.dubbo.config.ReferenceConfig.createProxy(ReferenceConfig.java:422) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.ReferenceConfig.init(ReferenceConfig.java:333) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.ReferenceConfig.get(ReferenceConfig.java:163) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.ReferenceBean.getObject(ReferenceBean.java:65) ~[dubbo-2.6.1.jar:2.6.1]
	... 30 more

Application didn't exit. Here we change log's level == warn. When starting application. It crash, throws exception like this

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'demoController': Injection of @Reference dependencies failed; nested exception is java.lang.IllegalStateException: Failed to check the status of the service com.fft.dubbo.consumer.service.DemoService. No provider available for the service com.fft.dubbo.consumer.service.DemoService:1.0.0 from the url zookeeper://localhost:2181/com.alibaba.dubbo.registry.RegistryService?application=dubbo-consumer-test&default=true&dubbo=2.6.1&interface=com.fft.dubbo.consumer.service.DemoService&methods=sayHello&pid=11847&register.ip=192.168.99.1&revision=1.0.0&side=consumer&timestamp=1542108310318&version=1.0.0 to the consumer 192.168.99.1 use dubbo version 2.6.1
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.postProcessPropertyValues(ReferenceAnnotationBeanPostProcessor.java:92) ~[dubbo-2.6.1.jar:2.6.1]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1264) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:866) ~[spring-context-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:542) ~[spring-context-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:122) ~[spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:737) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:370) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:314) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1162) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1151) [spring-boot-1.5.2.RELEASE.jar:1.5.2.RELEASE]
	at com.fft.dubbo.consumer.Application.main(Application.java:10) [classes/:?]
Caused by: java.lang.IllegalStateException: Failed to check the status of the service com.fft.dubbo.consumer.service.DemoService. No provider available for the service com.fft.dubbo.consumer.service.DemoService:1.0.0 from the url zookeeper://localhost:2181/com.alibaba.dubbo.registry.RegistryService?application=dubbo-consumer-test&default=true&dubbo=2.6.1&interface=com.fft.dubbo.consumer.service.DemoService&methods=sayHello&pid=11847&register.ip=192.168.99.1&revision=1.0.0&side=consumer&timestamp=1542108310318&version=1.0.0 to the consumer 192.168.99.1 use dubbo version 2.6.1
	at com.alibaba.dubbo.config.ReferenceConfig.createProxy(ReferenceConfig.java:422) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.ReferenceConfig.init(ReferenceConfig.java:333) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.ReferenceConfig.get(ReferenceConfig.java:163) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.buildReferenceBean(ReferenceAnnotationBeanPostProcessor.java:352) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.access$100(ReferenceAnnotationBeanPostProcessor.java:61) ~[dubbo-2.6.1.jar:2.6.1]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor$ReferenceFieldElement.inject(ReferenceAnnotationBeanPostProcessor.java:323) ~[dubbo-2.6.1.jar:2.6.1]
	at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:88) ~[spring-beans-4.3.7.RELEASE.jar:4.3.7.RELEASE]
	at com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.postProcessPropertyValues(ReferenceAnnotationBeanPostProcessor.java:88) ~[dubbo-2.6.1.jar:2.6.1]
	... 17 more

Here's dubbo-consumer-test

Also, if we didn't use log dependencies currently, there's no log also, it didn't crash either.

It seems that AbstractAnnotationConfigBeanBuilder#build() does this

public final B build() throws Exception {

        checkDependencies();

        B bean = doBuild();

        configureBean(bean);
        // use AbractConfig#toString
        if (logger.isInfoEnabled()) {
            logger.info(bean + " has been built.");
        }

        return bean;

    }

And AbstractConfig#toString()

@Override
    public String toString() {
        try {
            StringBuilder buf = new StringBuilder();
            buf.append("<dubbo:");
            buf.append(getTagName(getClass()));
            Method[] methods = getClass().getMethods();
            for (Method method : methods) {
                try {
                    String name = method.getName();
                    if ((name.startsWith("get") || name.startsWith("is"))
                            && !"getClass".equals(name) && !"get".equals(name) && !"is".equals(name)
                            && Modifier.isPublic(method.getModifiers())
                            && method.getParameterTypes().length == 0
                            && isPrimitive(method.getReturnType())) {
                        int i = name.startsWith("get") ? 3 : 2;
                        String key = name.substring(i, i + 1).toLowerCase() + name.substring(i + 1);
                        Object value = method.invoke(this, new Object[0]);
                        if (value != null) {
                            buf.append(" ");
                            buf.append(key);
                            buf.append("=\"");
                            buf.append(value);
                            buf.append("\"");
                        }
                    }
                } catch (Exception e) {
                    logger.warn(e.getMessage(), e);
                }
            }
            buf.append(" />");
            return buf.toString();
        } catch (Throwable t) {
            logger.warn(t.getMessage(), t);
            return super.toString();
        }
    }

It invoked getObject() method, and then catched logs, but not throwed. ReferenceAnnotationBeanPostProcessor#buildReferenceBean

private Object buildReferenceBean(Reference reference, Class<?> referenceClass) throws Exception {

        String referenceBeanCacheKey = generateReferenceBeanCacheKey(reference, referenceClass);

        ReferenceBean<?> referenceBean = referenceBeansCache.get(referenceBeanCacheKey);

        if (referenceBean == null) {

            ReferenceBeanBuilder beanBuilder = ReferenceBeanBuilder
                    .create(reference, classLoader, applicationContext)
                    .interfaceClass(referenceClass);

            referenceBean = beanBuilder.build();

            referenceBeansCache.putIfAbsent(referenceBeanCacheKey, referenceBean);

        }
        return referenceBean.get();
    }

If we use log's level greater than info, referenceBean.get() will work, the application will crash.

So, Dubbo should have the same behavior whatever log's level is?
@carryxyh
Copy link
Member

referenceBean.get() will not be executed in latest version:
#2759

@chutian52
Copy link
Author

@carryxyh 2.6.5 ?

@carryxyh
Copy link
Member

2.6.5-SNAPSHOT
this is not a release version.
but u can check this in 2.6.x branch.

@chutian52
Copy link
Author

@carryxyh Copy that, thanks a lot.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@chutian52 @carryxyh