You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@dubbo.apache.org by "chutian52 (GitHub)" <gi...@apache.org> on 2018/11/13 11:50:26 UTC

[GitHub] [incubator-dubbo] chutian52 opened issue #2784: Dubbo use diferent behavior when log's level greater than info

- [ ] I have searched the [issues](https://github.com/apache/incubator-dubbo/issues) of this repository and believe that this is not a duplicate.
- [ ] I have checked the [FAQ](https://github.com/apache/incubator-dubbo/blob/master/FAQ.md) 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);
}
```
2. 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);
    }
}
```
3. 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;
    }
}
```
4. Create a boot class
```
@SpringBootApplication
public class Application {

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }
}
```
5. 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](https://github.com/chutian52/dubbo-consumer-test.git)

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?

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org


[GitHub] [incubator-dubbo] carryxyh commented on issue #2784: Dubbo use diferent behavior when log's level greater than info

Posted by "carryxyh (GitHub)" <gi...@apache.org>.
2.6.5-SNAPSHOT
this is not a release version.
but u can check this in 2.6.x branch.

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org


[GitHub] [incubator-dubbo] carryxyh commented on issue #2784: Dubbo use diferent behavior when log's level greater than info

Posted by "carryxyh (GitHub)" <gi...@apache.org>.
`referenceBean.get()` will not be executed in latest version:
https://github.com/apache/incubator-dubbo/pull/2759

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org


[GitHub] [incubator-dubbo] chutian52 commented on issue #2784: Dubbo use diferent behavior when log's level greater than info

Posted by "chutian52 (GitHub)" <gi...@apache.org>.
@carryxyh  2.6.5 ?

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org


[GitHub] [incubator-dubbo] carryxyh closed issue #2784: Dubbo use diferent behavior when log's level greater than info

Posted by "carryxyh (GitHub)" <gi...@apache.org>.
[ issue closed by carryxyh ]

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org


[GitHub] [incubator-dubbo] chutian52 commented on issue #2784: Dubbo use diferent behavior when log's level greater than info

Posted by "chutian52 (GitHub)" <gi...@apache.org>.
@carryxyh Copy that, thanks a lot.

[ Full content available at: https://github.com/apache/incubator-dubbo/issues/2784 ]
This message was relayed via gitbox.apache.org for notifications@dubbo.apache.org