记一次线上问题-Druid数据源配置失败

一、背景是这样的

我们的服务是spring 服务。数据库是mysql。

接到公司要求， mysql数据源配置（JDBCURL地址）

jdbc:mysql://IP:PORT/dbname?Unicode=true&characterEncoding=utf8&useSSL=false

需要添加参数 allowMultiQueries=true。

也就是变成

jdbc:mysql://IP:PORT/dbname?Unicode=true&characterEncoding=utf8&useSSL=false&allowMultiQueries=true

配置是通过Apollo来动态实现的。

二、现象是这样的

当修改了Apollo，点击发布以后。同时监控系统进行了报警。

提示系统就出现了大量的 503错误。

我们有5个服务进行了修改。有两个服务出现了问题。 3个服务是没有问题的。

三、分析问题

1、由于有3个服务是没有问题的，所以第一反应不是因为修改Apollo导致的。

2、怀疑是网关出了问题。检查发现网关是正常的。

3、迅速查看了出问题的服务的日志。出现了Error级的日志。如下

log: |2024-03-07 10:13:20.552|ERROR|||[Failed to invoke config change listener com.ctrip.framework.apollo.spring.annotation.ApolloAnnotationProcessor$1]-[c.c.f.a.internals.AbstractConfig.java:445]-[Apollo-Config-4]
org.springframework.boot.context.properties.ConfigurationPropertiesBindException: Error creating bean with name 'dataSource': Could not bind properties to 'DruidDataSourceWrapper' : prefix=spring.datasource.druid, ignoreInvalidFields=false, ignoreUnknownFields=true; nested exception is org.springframework.boot.context.properties.bind.BindException: Failed to bind properties under 'spring.datasource.druid' to javax.sql.DataSource
	at org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor.bind(ConfigurationPropertiesBindingPostProcessor.java:110)
	at org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor.postProcessBeforeInitialization(ConfigurationPropertiesBindingPostProcessor.java:93)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:416)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1686)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:407)
	at org.springframework.cloud.context.properties.ConfigurationPropertiesRebinder.rebind(ConfigurationPropertiesRebinder.java:102)
	at org.springframework.cloud.context.properties.ConfigurationPropertiesRebinder.rebind(ConfigurationPropertiesRebinder.java:84)
	at org.springframework.cloud.context.properties.ConfigurationPropertiesRebinder.onApplicationEvent(ConfigurationPropertiesRebinder.java:128)
	at org.springframework.cloud.context.properties.ConfigurationPropertiesRebinder.onApplicationEvent(ConfigurationPropertiesRebinder.java:50)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:400)
	at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:354)Java

看到报错否定了第一个反应，看来是由于这个数据源配置变化导致的。继续找到如下日志

Caused by: java.lang.IllegalStateException: Unable to set value for property url
	at org.springframework.boot.context.properties.bind.JavaBeanBinder$BeanProperty.setValue(JavaBeanBinder.java:323)
	at org.springframework.boot.context.properties.bind.JavaBeanBinder.bind(JavaBeanBinder.java:79)
	at org.springframework.boot.context.properties.bind.JavaBeanBinder.bind(JavaBeanBinder.java:62)
	at org.springframework.boot.context.properties.bind.JavaBeanBinder.bind(JavaBeanBinder.java:54)
	at org.springframework.boot.context.properties.bind.Binder.lambda$null$5(Binder.java:341)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1359)
	at java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126)
	at java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:499)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:486)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
	at java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:152)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:531)
	at org.springframework.boot.context.properties.bind.Binder.lambda$bindBean$6(Binder.java:342)
	at org.springframework.boot.context.properties.bind.Binder$Context.withIncreasedDepth(Binder.java:441)
	at org.springframework.boot.context.properties.bind.Binder$Context.withBean(Binder.java:427)
	at org.springframework.boot.context.properties.bind.Binder$Context.access$400(Binder.java:381)
	at org.springframework.boot.context.properties.bind.Binder.bindBean(Binder.java:339)
	at org.springframework.boot.context.properties.bind.Binder.bindObject(Binder.java:278)
	at org.springframework.boot.context.properties.bind.Binder.bind(Binder.java:221)

正是提示我们刚修改的url set 失败。

4、下面检查了一下没有出问题的项目和出问题的项目配置之间的差距，发现

出问题的配置是：spring.datasource.druid.url = jdbc:mysql://***

没问题的配置是：spring.datasource.url = jdbc:mysql://***

那么锁定问题是druid在出现Apollo配置更新的时候出现了问题。

5、下一步就是赶紧重新启动服务。保证服务正常。后续在测试环境复现问题，查找根本原因。

四、找到问题原因

1、测试环境进行了测试，没有发现问题。认真一看发现出问题的服务在测试并没有配置成 spring.datasource.druid.url 而是 spring.datasource.url。所以，在测试环境没有出问题。

2、在测试环境配置成druid的方式。进行测试。果然复现了问题。

过程是这样的

首先：Apollo的配置变化的Listener接收到变化事件。触发了更新Spring容器内Bean 的操作（公司自己的starter）。

代码如下：

  @ApolloConfigChangeListener
    public void onChange(ConfigChangeEvent changeEvent) {
        Set<String> changedKeys = changeEvent.changedKeys();
        if (null != changedKeys) {
            Iterator var3 = changedKeys.iterator();

            while(var3.hasNext()) {
                String key = (String)var3.next();
                ConfigChange change = changeEvent.getChange(key);
                log.info("apollo配置变更,[{}]发生[{}]变更:[{}]==>[{}]", new Object[]{key, change.getChangeType(), change.getOldValue(), change.getNewValue()});
            }
        }

        this.applicationContext.publishEvent(new EnvironmentChangeEvent(changeEvent.changedKeys()));
        if (null != this.refreshScope) {
            this.refreshScope.refreshAll(); 
        }

    }

然后会走到Apollo代码里面，使用反射调用对应Bean的set 方法，对Apollo 配置变化的key进行重新设置。

  ReflectionUtils.makeAccessible(method);
    String[] namespaces = annotation.value();
    String[] annotatedInterestedKeys = annotation.interestedKeys();
    Set<String> interestedKeys = annotatedInterestedKeys.length > 0 ? Sets.newHashSet(annotatedInterestedKeys) : null;
    ConfigChangeListener configChangeListener = new ConfigChangeListener() {
      @Override
      public void onChange(ConfigChangeEvent changeEvent) {
        ReflectionUtils.invokeMethod(method, bean, changeEvent); //这一行就在日志异常中能看到了，也是从这里找到的原因
      }
    };

这里的 invokeMethod 会调用对应的set 方法。这里对应的就是 DruidAbstractDataSource类里面的setUrl

 public void setUrl(String jdbcUrl) {
        if (StringUtils.equals(this.jdbcUrl, jdbcUrl)) {
            return;
        }

        if (inited) {
            throw new UnsupportedOperationException();
        }

        if (jdbcUrl != null) {
            jdbcUrl = jdbcUrl.trim();
        }

        this.jdbcUrl = jdbcUrl;

        // if (jdbcUrl.startsWith(ConfigFilter.URL_PREFIX)) {
        // this.filters.add(new ConfigFilter());
        // }
    }

在这里我们发现了 if (inited) 这个条件，一旦出现true ，那么就会跑出异常。这也就是根本原因。原来 Druid 在进行数据源配置的时候会判断当前是否已经进行了初始化。如果已经inited，就不允许在进行重新设置。

查看了 if (inited) 这个条件同时出现在很多其他的地方。比如设置数据库用户名、设置密码。都存在这个限制。

3、进一步看一下， inited 在什么时候会发生改变。

在init 的时候，设置为true 。在restart 的时候会设置为false：

public void restart() throws SQLException {
        lock.lock();
        try {
            if (activeCount > 0) {
                throw new SQLException("can not restart, activeCount not zero. " + activeCount);
            }
            if (LOG.isInfoEnabled()) {
                LOG.info("{dataSource-" + this.getID() + "} restart");
            }

            this.close();
            this.resetStat();
            this.inited = false;
            this.enable = true;
            this.closed = false;
        } finally {
            lock.unlock();
        }
    }

也就是说，修改Apollo配置的时候，并不会restart druid数据源。导致设置失败。

致辞问题发现并解决，后续使用过程中需要注意。当然修改Apollo其他配置不会导致这个问题。