docker升级nacos到2.2.3,单机启动提示errCode: 500, errMsg: load schema.sql error.

2,723 阅读3分钟

docke升级nacos升级到2.2.3时,单机启动启动失败,报错日志如下


2021-09-18 22:40:32,148 INFO Root WebApplicationContext: initialization completed in 11864 ms

2021-09-18 22:40:44,722 ERROR Error starting Tomcat context. Exception: org.springframework.beans.factory.BeanCreationException. Message: Error creating bean with name 'authFilterRegistration' defined in class path resource [com/alibaba/nacos/core/auth/AuthConfigs.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [org.springframework.boot.web.servlet.FilterRegistrationBean]: Factory method 'authFilterRegistration' threw exception; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'authFilter': Unsatisfied dependency expressed through field 'authManager'; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'nacosAuthManager': Unsatisfied dependency expressed through field 'authenticationManager'; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'nacosAuthConfig': Unsatisfied dependency expressed through field 'userDetailsService'; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'nacosUserDetailsServiceImpl': Unsatisfied dependency expressed through field 'userPersistService'; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'embeddedUserPersistServiceImpl': Unsatisfied dependency expressed through field 'databaseOperate'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'standaloneDatabaseOperateImpl': Invocation of init method failed; nested exception is java.lang.RuntimeException: com.alibaba.nacos.api.exception.runtime.NacosRuntimeException: errCode: 500, errMsg: load schema.sql error.

2021-09-18 22:40:44,827 WARN Exception encountered during context initialization - cancelling refresh attempt: org.springframework.context.ApplicationContextException: Unable to start web server; nested exception is org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat

2021-09-18 22:40:44,837 INFO Nacos Log files: /home/nacos/logs

2021-09-18 22:40:44,849 INFO Nacos Log files: /home/nacos/conf

2021-09-18 22:40:44,853 INFO Nacos Log files: /home/nacos/data

2021-09-18 22:40:44,856 ERROR Startup errors : {}

org.springframework.context.ApplicationContextException: Unable to start web server; nested exception is org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat
        at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:157)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:540)
...............
Caused by: com.alibaba.nacos.api.exception.runtime.NacosRuntimeException: errCode: 500, errMsg: load schema.sql error.
        at com.alibaba.nacos.config.server.service.datasource.LocalDataSourceServiceImpl.reload(LocalDataSourceServiceImpl.java:101)
        at com.alibaba.nacos.config.server.service.datasource.LocalDataSourceServiceImpl.initialize(LocalDataSourceServiceImpl.java:170)
        at com.alibaba.nacos.config.server.service.datasource.LocalDataSourceServiceImpl.init(LocalDataSourceServiceImpl.java:83)
        at com.alibaba.nacos.config.server.service.datasource.DynamicDataSource.getDataSource(DynamicDataSource.java:47)
        ... 166 common frames omitted

每次启动其实异常都有点细微的差别,而且docker compose up多次之后还有几率能成功,就让我很奇怪,经过对比后发现到这里的异常都是一样的,所以锁定到了 reload方法

@Override
public synchronized void reload() {
    DataSource ds = jt.getDataSource();
    if (ds == null) {
        throw new RuntimeException("datasource is null");
    }
    try {
        execute(ds.getConnection(), "META-INF/derby-schema.sql");
    } catch (Exception e) {
        if (LOGGER.isErrorEnabled()) {
            LOGGER.error(e.getMessage(), e);
        }
        throw new NacosRuntimeException(NacosException.SERVER_ERROR, "load derby-schema.sql error.", e);
    }
}

果然有一模一样的异常信息打印

throw new NacosRuntimeException(NacosException.SERVER_ERROR, "load derby-schema.sql error.", e);

但是还是没什么思路,execute只是执行sql语句,就只能往前推看到initialize方法

private synchronized void initialize(String jdbcUrl) {
    DataSourcePoolProperties poolProperties = DataSourcePoolProperties.build(EnvUtil.getEnvironment());
    poolProperties.setDriverClassName(jdbcDriverName);
    poolProperties.setJdbcUrl(jdbcUrl);
    poolProperties.setUsername(userName);
    poolProperties.setPassword(password);
    HikariDataSource ds = poolProperties.getDataSource();
    DataSourceTransactionManager tm = new DataSourceTransactionManager();
    tm.setDataSource(ds);
    if (jdbcTemplateInit) {
        jt.setDataSource(ds);
        tjt.setTransactionManager(tm);
    } else {
        jt = new JdbcTemplate();
        jt.setMaxRows(50000);
        jt.setQueryTimeout(5000);
        jt.setDataSource(ds);
        tjt = new TransactionTemplate(tm);
        tjt.setTimeout(5000);
        jdbcTemplateInit = true;
    }
    reload();
}

DataSourcePoolProperties 这个类读取各种datasource配置的

public static final long DEFAULT_CONNECTION_TIMEOUT = TimeUnit.SECONDS.toMillis(3L);

public static final long DEFAULT_VALIDATION_TIMEOUT = TimeUnit.SECONDS.toMillis(10L);

public static final long DEFAULT_IDLE_TIMEOUT = TimeUnit.MINUTES.toMillis(10L);

public static final int DEFAULT_MAX_POOL_SIZE = 20;

public static final int DEFAULT_MINIMUM_IDLE = 2;

private final HikariDataSource dataSource;

其中 DEFAULT_CONNECTION_TIMEOUT 默认为3秒,看日志输出报错,确实就是三秒左右有提示超时。 起初我以为是sql文件过大,加载很慢导致超时了,想说设置一下超时时间,但是我用的又是nacos默认的Derby,一直找不到配置项是哪个。就在绝望的时候,突然看到了异常里有一闪而过的/home/nacos/data/derby-data 不存在的异常。卧槽,想到不会是镜像里没有derby-data的配置吧。重启了一下nacos,执行

docker exec nacos cat /home/nacos/data/derby-data/application.properties

还真的文件不存在。。。。 那后面就简单了,从本地复制一个到docker镜像中就好了

docker cp /usr/local/service.properties nacos:/home/nacos/data/derby-data

然后重新compose up一下,操,可以了。 但是我在搜寻资料的时候,确实也遇到过有人是真的执行默认sql脚本超时了 所以总的来说 如果提示了单机启动提示了errCode: 500, errMsg: load schema.sql error. 首先考虑derby-data中的文件是否都存在,如果都存在,提高derby的连接时长,不太可能真的是登录超时之类的问题