springboot的 nacos 配置获取不到导致启动失败及日志不输出问题

前言

问题

1. 本地启动应用时，一切正常，但是部署 docker 后，会因为获取不到 nacos 中的配置导致服务启动失败。
2.当 docker 中的服务一直重启，可能会突然某一次启动成功，之后只要不重新构建 docker 镜像，就不会再出现 nacos 配置获取不到的问题。
3.明明获取不到 nacos 配置，但是却没有输出任何 nacos 相关的日志

配置

springboot 2.7.15 有提供两种 nacos 配置方式，一种是用 bootstrap.yml，另一种采用的是spring.config.import。我使用的是 spring.config.import 方式,配置如下所示。( nacos 配置加载流程可以看 nacos配置加载流程)

spring:
    cloud:
        nacos:
            config:
                server-addr: ${ip}
                namespace: ${port}
    config:
        import:
            - optional:nacos:app.yaml

docker 使用的是 host 模式

解决方案：

配置获取不到问题

nacos 角度

从 nacos 角度排查的原因是因为nacos 服务端服务检测超时了,所以可以增加检测的超时时间。修改启动命令如下所示

java -Dnacos.remote.client.grpc.server.check.timeout=5000 -jar app.jar

当然这种方法治标不治本，应该解决的是为什么会超时，但是从 nacos 方面没定位出来为什么超时。但本文主要讲的是 nacos 方面的问题ding'we

非nacos的角度

docker 日志中可以看到 InetAddress.getLocalHost().getHostName took 10007 之类的错误,如下图所示，根据这个错误百度会发现是因为没有在 hosts 配置主机名导致的获取超时，且是在 host 模式才会。

还有就是 docker 在 bridge 模式下也不会上述问题

上面的错误是出于 spring，并非出于 nacos，非本文重点，后续不会再次说明。

nacos 日志不输出问题

只需要用如下配置即可在容器中的 remote.log 中看到相关的日志信息

public static void main(String[] args) {
	SpringApplication springApplication = new SpringApplication(SimAppExperimentApplication.class);
	springApplication.addListeners(new LoggingListener());
	springApplication.run(args);
}

  
public static class LoggingListener implements ApplicationListener<ApplicationEnvironmentPreparedEvent>, Ordered {
	@Override
	public int getOrder() {
		return LoggingSystemShutdownListener.DEFAULT_ORDER + 1;
	}

	@Override
	public void onApplicationEvent(ApplicationEnvironmentPreparedEvent event) {

		//用这种方法目前测试会导致服务启动后的一些日志无法输出
//            LoggingSystem loggingSystem = LoggingSystem.get(ClassUtils.getDefaultClassLoader());
//            loggingSystem.cleanUp();

		ILoggerFactory factory = StaticLoggerBinder.getSingleton().getLoggerFactory();
		Assert.isInstanceOf(LoggerContext.class, factory,
				() -> String.format(
						"LoggerFactory is not a Logback LoggerContext but Logback is on "
								+ "the classpath. Either remove Logback or the competing "
								+ "implementation (%s loaded from %s). If you are using "
								+ "WebLogic you will need to add 'org.slf4j' to "
								+ "prefer-application-packages in WEB-INF/weblogic.xml",
						factory.getClass(), getLocation(factory)));
		LoggerContext loggerContext = (LoggerContext) factory;
		loggerContext.getTurboFilterList().clear();
    }


	private Object getLocation(ILoggerFactory factory) {
		try {
			ProtectionDomain protectionDomain = factory.getClass().getProtectionDomain();
			CodeSource codeSource = protectionDomain.getCodeSource();
			if (codeSource != null) {
				return codeSource.getLocation();
			}
		} catch (SecurityException ex) {
			// Unable to determine location
		}
		return "unknown location";
	}
}

然后就可以在 remote.log 文件里看到对应的 nacos 日志输出

之所以是在 remote.log 里，是因为 nacos-client.jar 的 nacos-lombok.xml 配置了输出方式

上述配置调试 nacos 问题的时候可以用，但不建议放生产环境，因为不确定是否会出现莫名其妙的情况

问题分析

配置获取不到问题

注意:下面的代码图片中可以看到好多地方都是有输出相关的错误日志的，但是在服务器中却无法看到相关的日志。导致问题不好排查。

nacos 配置加载流程可以看 nacos配置加载流程

本文 nacos 的配置获取是在 EnvironmentPostProcessorApplicationListener 中监听到 ApplicationEnvironmentPreparedEventEvent 事件后触发的。

然后获取配置时的第一个错误是在 NacosConfigService.getConfigInner ，异常信息为 ErrCode:-401,ErrorMsg:Client not connected, current status:STARTING ，具体如下图所示

上面的错误是因为 RpcClient.request 执行的时候，RpcClient 的status 是STARTING，而非RUNNING ，具体如下图所示

RpcClient 的 status 是在 RpcClient.start 里面设置为 running。设置分为同步和异步。

1.同步设置

如下图所示，RpcClient.start 会直接调用 RpcClient.connectToServer 连接nacos。一旦连接成功就会将 status 设置为 running。如下图所示

然后在 RpcClient.connectToServer 连接过程中，会在 RpcClient.connectToServer ,如下图所示

而这里一旦连接 nacos 超时，那自然就无法获取到 nacos 服务端的相关配置，启动服务也会因为无关键配置而报错失败。

所以从这方面看，解决就可以考虑增加超时时间(默认3s)。当然，如果继续深入排查，也许也能发现是因为 hosts 没有配置主机映射导致的。但只是到这个地方的话，我是没想到为什么请求localhost:9848,怎么会因为 hosts 没有配置主机名而超时呢？难不成请求的时候还会基于主机名进行 dns 查询吗？

2.异步设置

由于是异步设置，所以即使异步能成功，但是服务启动的时候是不会等异步成功后在去加载配置的。

如下图所示，当同步设置没成功时，会开启异步任务重新连接 nacos (红框标错，异步任务是最后一行 switchServerAsync 触发的。后续再调整)

然后会在 RpcClient.reconnect 中进行重连，成功后也会把 status 改为 RUNNING

日志不输出问题

首先，在LoggingApplicationListener 会监听 ApplicationStartingEvent事件，然后调用 LoggingSystem.beforeInitalize 方法

logback 的 LoggingSystem.beforeInitalize 方法会添加一个 TurboFilter

这个TurboFilter 会直接 return FilterReply.DENY

而当 logger 在打日志的时候，会校验是否开启对应的日志 level(info、debug 等)，这个校验会调用所有的 TurboFilter 进行，当有 TurboFilter 拿到 FilterReply.DENY的时候就不会输出日志

然后LoggingSystemShutdownListener在接收到ApplicationEnvironmentPreparedEventEvent 后也会触发添加一个固定返回 FilterReply.DENY 的TurboFilter 。这个是在在LoggingApplicationListener 接收 ApplicationEnvironmentPreparedEventEvent 逻辑之前执行的

而该 TurboFilter 的会在 LoggingApplicationListener 接收到ApplicationEnvironmentPreparedEventEvent 时间后移除(initialize 里面的逻辑)

综上所述在LoggingApplicationListener接收ApplicationStartingEvent 和ApplicationEnvironmentPreparedEventEvent 之间的时间内，Logger 是无法正常输出的。(不只局限于nacos)

而要解决该问题，就需要在LoggingSystemShutdownListener 接收到ApplicationEnvironmentPreparedEventEvent 之后,EnvironmentPostProcessorApplicationListener ApplicationEnvironmentPreparedEventEvent 接受到ApplicationEnvironmentPreparedEventEvent 之前，将对应的 TurboFilter 移除，即前面的解决方案。