kl小陈个人页面-阿里云开发者社区

给gRPC-spring-boot-starter一个pr的说明

前言为了更好的说明给gRPC-spring-boot-starter项目提交bug修复的pr的原因，解答作者的问题。以博文的形式记录了整个过程的上下文，目前pr未合并还在沟通处理中，希望此博文可以更清楚描述问题 pr地址：https://github.com/yidongnan/grpc-spring-boot-starter/pull/454 gRPC-spring-boot-starter是什么？这是一个spring-boot-starter项目，用来在spring boot框架下，快速便捷的使用grpc技术，开箱即用。它提供如下等功能特性：在 spring boot 应用中，通过@GrpcService自动配置并运行一个嵌入式的 gRPC 服务。使用@GrpcClient自动创建和管理您的 gRPC Channels 和 stubs 支持Spring Cloud(向Consul或Eureka或Nacos注册服务并获取 gRPC 服务端信息) 支持Spring Sleuth作为分布式链路跟踪解决方案(如果brave-instrument-grpc存在) 支持全局和自定义的 gRPC 服务端/客户端拦截器支持Spring-Security 支持metric (基于micrometer/actuator) 也适用于 (non-shaded) grpc-netty 选型gRPC-spring-boot-starter 博主新入职公司接手的项目采用grpc做微服务通讯框架，项目底层框架采用的spring boot，然后grpc的使用是纯手工配置的，代码写起来比较繁琐，而且这种繁琐的模板化代码充斥在每个采用了grpc的微服务项目里。所以技术选型后找到了gRPC-spring-boot-starter 这个开源项目，这个项目代码质量不错，非常规范，文档也比较齐全。但是鉴于之前工作经验遇到过开源项目的问题（博主选型的原则，如果有合适的轮子，就摸透这个轮子，然后基于这个轮子二开，没有就自己造一个轮子），而且一般解决周期比较长，所以最后，我们没有直接采用他们的发行包，而是fork了项目后，打算自己维护。正因为如此，才为后面迅速解决问题上线成为可能。也验证了二开这个选择是正确的。 bug出现，grpc未优雅下线风风火火重构了所有代码，全部换成gRPC-spring-boot-starter后就上线了，上线后一切都非常好，但是项目在第二次需求上线投产时发生了一些问题。这个时候还不确定是切换grpc实现导致的问题，现象就是，线上出现了大量的请求异常。上线完成后，异常就消失了。后面每次滚动更新都会出现类似的异常。这个时候就很容易联系到是否切换grpc实现后，grpc未优雅下线，导致滚动更新时，大量的进行中的请求未正常处理，导致这部分流量异常？因为我们线上流量比较大，几乎每时每刻都有大量请求，所以我们要求线上服务必须支持无缝滚动更新。如果流量比较小，这个问题可能就不会暴露出来，这也解释了之前和同事讨论的点，为什么这么明显的问题没有被及早的发现。不过都目前为止，这一切都只是猜测，真相继续往下。定位bug，寻找真实原因有了上面的猜测，直接找到了gRPC-spring-boot-starter管理维护GrpcServer生命周期的类GrpcServerLifecycle，这个类实现了spring的SmartLifecycle接口，这个接口是用来注册SpringContextShutdownHook的钩子用的，它的实现如下： @Slf4j public class GrpcServerLifecycle implements SmartLifecycle { private static AtomicInteger serverCounter = new AtomicInteger(-1); private volatile Server server; private volatile int phase = Integer.MAX_VALUE; private final GrpcServerFactory factory; public GrpcServerLifecycle(final GrpcServerFactory factory) { this.factory = factory; } @Override public void start() { try { createAndStartGrpcServer(); } catch (final IOException e) { throw new IllegalStateException("Failed to start the grpc server", e); } } @Override public void stop() { stopAndReleaseGrpcServer(); } @Override public void stop(final Runnable callback) { stop(); callback.run(); } @Override public boolean isRunning() { return this.server != null && !this.server.isShutdown(); } @Override public int getPhase() { return this.phase; } @Override public boolean isAutoStartup() { return true; } /** * Creates and starts the grpc server. * * @throws IOException If the server is unable to bind the port. */ protected void createAndStartGrpcServer() throws IOException { final Server localServer = this.server; if (localServer == null) { this.server = this.factory.createServer(); this.server.start(); log.info("gRPC Server started, listening on address: " + this.factory.getAddress() + ", port: " + this.factory.getPort()); // Prevent the JVM from shutting down while the server is running final Thread awaitThread = new Thread(() -> { try { this.server.awaitTermination(); } catch (final InterruptedException e) { Thread.currentThread().interrupt(); } }, "grpc-server-container-" + (serverCounter.incrementAndGet())); awaitThread.setDaemon(false); awaitThread.start(); } } /** * Initiates an orderly shutdown of the grpc server and releases the references to the server. This call does not * wait for the server to be completely shut down. */ protected void stopAndReleaseGrpcServer() { final Server localServer = this.server; if (localServer != null) { localServer.shutdown(); this.server = null; log.info("gRPC server shutdown."); } } } 也就是说当spring容器关闭时，会触发ShutdownHook，进而关闭GrpcServer服务，问题就出现在这里，从stopAndReleaseGrpcServer()方法可知，Grpc进行shudown()后，没有进行任何操作，几乎瞬时就返回了，这就导致了进程在收到kill命令时，Grpc的服务会被瞬间回收掉，而不会等待执行中的处理完成，这个判断可以从shutdown()的文档描述中进一步得到确认，如： /** * Initiates an orderly shutdown in which preexisting calls continue but new calls are rejected. * After this call returns, this server has released the listening socket(s) and may be reused by * another server. * * <p>Note that this method will not wait for preexisting calls to finish before returning. * {@link #awaitTermination()} or {@link #awaitTermination(long, TimeUnit)} needs to be called to * wait for existing calls to finish. * * @return {@code this} object * @since 1.0.0 */ public abstract Server shutdown(); 文档指出，调用shutdown()后，不在接收新的请求流量，进行中的请求会继续处理完成，但是请注意，它不会等待现有的调用请求完成，必须使用awaitTermination()方法等待请求完成，也就是说，这里处理关闭的逻辑里，缺少了awaitTermination()等待处理中的请求完成的逻辑。模拟环境，反复验证验证方法：这个场景的问题非常容易验证，只需要在server端模拟业务阻塞耗时长一点，然后kill掉java进程，看程序是否会立刻被kill。正常优雅下线关闭的话，会等待阻塞的时间后进程kill。否则就会出现不管业务阻塞多长时间，进程都会立马kill。验证定位的bug 先验证下是否如上面所说，不加awaitTermination()时，进程是否立马就死了。直接使用gRPC-spring-boot-starter里自带的demo程序，在server端的方法里加上如下模拟业务执行耗时的代码： @GrpcService public class GrpcServerService extends SimpleGrpc.SimpleImplBase { @Override public void sayHello(HelloRequest req, StreamObserver<HelloReply> responseObserver) { HelloReply reply = HelloReply._newBuilder_().setMessage("Hello ==> " \+ req.getName()).build(); try { System._err_.println("收到请求，阻塞等待"); TimeUnit._MINUTES_.sleep(1); System._err_.println("阻塞完成，请求结束"); } catch (InterruptedException e) { e.printStackTrace(); } responseObserver.onNext(reply); responseObserver.onCompleted(); } } 上面代码模拟的执行一分钟的方法，然后触发grpc client调用。接着找到server端的进程号，直接kill掉。发现进程确实立马就kill了。继续加大阻塞的时间，从一分钟加大到六分钟，重复测试，还是立马就kill掉了，没有任何的等待。验证修复后的效果先将上面的代码修复下，正确的关闭逻辑应该如下，在Grpc发出shutdown指令后，阻塞等待所有请求正常结束，同时，这里阻塞也会夯住主进程不会里面挂掉。 protected void stopAndReleaseGrpcServer() { final Server localServer = this.server; if (localServer != null) { localServer.shutdown(); try { this.server.awaitTermination(); } catch (final InterruptedException e) { Thread.currentThread().interrupt(); } this.server = null; log.info("gRPC server shutdown."); } } 同样，如上述步骤验证，当kill掉java进程后，此时java进程并没有立马就被kill，而是被awaitTermination()阻塞住了线程，直到业务方法中模拟的业务阻塞结束后，java进程才被kill掉，这正是我们想要达到的优雅下线关闭的效果。被kill时的，线程堆栈如下：即使被kill了，还是能打印如下的日志【阻塞完成，请求结束】，进一步验证了修复后确实解决了问题：

集成apollo动态日志，“消灭”logback-spring.xml

前言动态调整线上日志级别是一个非常常见的场景，借助apollo这种配置中心组件非常容易实现。作为apollo的官方技术支持，博主经常在技术群看到有使用者询问apollo是否可以托管logback的配置文件，毕竟有了配置中心后，消灭所有的本地配置全部交给apollo管理是我们的最终目标。可是，apollo不具备直接托管logback-spring.xml配置文件能力，但是，我们可以基于spring和logback的装载机制，完全取缔logback-spring.xml配置，以apollo中的配置驱动。而且，改造后，大大提高了日志系统的灵活性和可扩展性。 apollo动态日志何为apollo动态日志？直接这样说可能会有歧义，以为是apollo里的日志，其实不然。举个简单的例子，比如，我们项目很多地方使用了log.debug()打印日志，为了方便通过日志信息排查问题，但是一般情况下，生产环境的日志级别会配置成info。只有遇到需要排查线上问题的时候才会临时打开debug级别日志。这个时候只能需改配置文件，将日志级别调整成debug，然后重新打包部署验证。不仅流程繁琐耗时，还会破坏当时的"案发现场的环境"，导致判断不准确。如果应用具备了apollo动态日志这种能力，就只需在apollo修改下配置然后提交，就可以热更新日志级别，马上打印debug级别日志。这就是所谓的apollo动态日志。实现这个效果，需要具备两个能力，分别由spring和apollo提供 spring日志系统热更新日志级别 spring应用中，spring适配了主流的日志框架，如logback、log4j2等，在这些日志框架之上，又抽象了自己的日志系统服务，这里我们用到了spring的LoggingSystem，用它来热更新日志级别，这个类在日志系统初始化时就添加到了spring的容器中，所以只要在spring的上下文管理范围内，就可以直接注入，以下为主要使用到的api描述： /** * 设置给定日志记录器的日志级别. * @param loggerName 要设置的日志记录器的名称({@code null}可用于根日志记录器)。 * @param level 日志级别 */ public void setLogLevel(String loggerName, LogLevel level) { throw new UnsupportedOperationException("Unable to set log level"); } apollo日志配置变更动态下发 apollo作为分布式配置中心，配置集中管理和配置热更新是其最核心的功能，此外，apollo还提供了配置变更下发监听的功能。基于这个配置监听的设计，实现动态日志就变得非常简单了。而且不仅可以实现日志动态热更，基于这个思路，连接池、数据源等都可以轻松实现。apollo实现监听配置变更有多种方式，可以通过Config实例手动添加，如： @ApolloConfig public Config config; public void addConfigChangeListener(){ config.addChangeListener(changeEvent->{ System.out.println("config change keys" + changeEvent.changedKeys()); }); } 也可以通过注解直接驱动 @ApolloConfigChangeListener public void addConfigChangeListener(ConfigChangeEvent changeEvent){ System.out.println("config change keys" + changeEvent.changedKeys()); } 实现日志调整热更新有了上述能力，在结合spring支持的日志加载配置方式，如： logging.level.org.springframework.web=debug logging.level.org.hibernate=error 可以实现如下代码完成功能，遇到需要调整日志级别时，修改apollo里的配置，即可实时生效 @Configuration public class LogbackConfiguration { private static final Logger logger = LoggerFactory.getLogger(LoggerConfiguration.class); private static final String LOGGER_TAG = "logging.level."; private final LoggingSystem loggingSystem; public LogbackConfiguration(LoggingSystem loggingSystem) { this.loggingSystem = loggingSystem; } @ApolloConfigChangeListener private void onChange(ConfigChangeEvent changeEvent) { for (String key : changeEvent.changedKeys()) { if (this.containsIgnoreCase(key, LOGGER_TAG)) { String strLevel = changeEvent.getChange(key).getNewValue(); LogLevel level = LogLevel.valueOf(strLevel.toUpperCase()); loggingSystem.setLogLevel(key.replace(LOGGER_TAG, ""), level); logger.info("logging changed: {},oldValue:{},newValue:{}", key, changeEvent.getChange(key).getOldValue(), strLevel); } } } private boolean containsIgnoreCase(String str, String searchStr) { if (str == null || searchStr == null) { return false; } int len = searchStr.length(); int max = str.length() - len; for (int i = 0; i <= max; i++) { if (str.regionMatches(true, i, searchStr, 0, len)) { return true; } } return false; } } 消灭logback-spring.xml配置在"消灭"logback-xml配置之前，先看下这个配置文件有哪些配置信息，起到了哪些作用，下面贴出一个典型的配置文件内容： <?xml version="1.0" encoding="UTF-8"?> <configuration> <include resource="org/springframework/boot/logging/logback/defaults.xml"/> <include resource="org/springframework/boot/logging/logback/console-appender.xml"/> <appender name="Sentry" class="io.sentry.logback.SentryAppender"> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>ERROR</level> </filter> </appender> <root level="INFO"> <appender-ref ref="CONSOLE"/> <appender-ref ref="Sentry"/> </root> <logger name="org.apache.ibatis.session" level="WARN"/> <springProfile name="dev"> <logger name="com.taptap.server" level="DEBUG"/> <logger name="com.taptap.commons" level="DEBUG"/> </springProfile> <springProfile name="prod"> <logger name="com.taptap.server" level="WARN"/> <logger name="com.taptap.commons" level="WARN"/> </springProfile> </configuration> 一个典型的logback配置文件里包含了Appender和日志级别设置的信息，Appender可以理解为日志的输出源。如上贴出的这个配置，添加了两个Appender信息，一个是spring中内置的，将日志输出到控制台的Appender。一个是将error日志信息发送到Sentry应用监控平台的Appender。其他的配置描述了每个包路径不同的日志级别信息。到这里，我们很容易想到，上文已经说过，spring已经支持以logging.level.包名=info这种配置来设置日志系统的日志级别。那么剩下的只要解决Appender的配置就ok了。在这里，其实只需要解决SentryAppender的加载就行，因为consoleAppender spring自己会处理。有了目标和方向，就好办了。以logback-spring.xml配置的信息，最终都会加载成class对象。就和spring.xml配置一样。所以研究的方向就变成了Logback的加载原理的问题。 Logback加载原理在java的日志生态里，除了响当当的logback、log4j2、apache common log外，还有一个日志框架不得不提，就是sl4j。正因为java生态强大，日志框架层出不穷，所以sl4j出来了，不干实事，专门定义日志标准、规范定义接口。而且，在我们平时的编码过程中，也建议使用sl4j的api，这样，无论底层日志框架实现怎么切换，都不会影响。主流的日志框架都有实现sl4j的接口，spring中日志系统的加载也是面向的sl4j，而不是直接面向日志实现，加载过程是一个自动化的过程，系统会自动扫描实现了sl4j的接口实现，如： public interface ILoggerFactory { public Logger getLogger(String name); } 每个日志框架都会实现这个接口，如Logback中的LoggerContext。Logback所有的功能都集成在了这个Context中，logback-spring.xml的配置也是为了配置LoggerContext中的属性信息，所有我们只要拿到了LoggerContext实例，问题就解决了一大半。这涉及到sl4j的另一个接口，获取ILoggerFactory实例的接口： public interface LoggerFactoryBinder { public ILoggerFactory getLoggerFactory(); public String getLoggerFactoryClassStr(); } Logback的实现类为StaticLoggerBinder，也就是说，我们可以通过StaticLoggerBinder的getLoggerFactory方法拿到LoggerContext实例了。 javaBean加载SentryAppender 拿到Logback的LoggerContext后，就好办了，见代码： @Configuration public class LogbackConfiguration { private final LoggerContext ctx = (LoggerContext) StaticLoggerBinder.getSingleton().getLoggerFactory(); @Bean @Profile(PROD_ENV) public void initSenTry() { SentryAppender sentryAppender = new SentryAppender(); sentryAppender.setContext(ctx); ThresholdFilter filter = new ThresholdFilter(); filter.setLevel(Level.ERROR.levelStr); filter.start(); sentryAppender.addFilter(filter); sentryAppender.start(); ctx.addTurboFilter(new TurboFilter() { @Override public FilterReply decide(Marker marker, ch.qos.logback.classic.Logger logger, Level level, String format, Object[] params, Throwable t) { logger.addAppender(sentryAppender); return FilterReply.NEUTRAL; } }); } } 看到这种代码就非常有感觉了，配置文件中的xml其实就是描述了日志组成对象以及对象的属性。在使用java bean的方式配置时需要注意，Logback的设计里，每个日志系统组成实例都有一个start状态属性，上面的start()方法其实不是动作，只是标记了这个属性为true。而在xml里这个属性只要配置了就自动激活为true了，这里必须显示的start()一下。解决了日志级别配置和Appender配置后，Logback-spring.xml文件就可以彻底的删除了

kl小陈个人页面-阿里云开发者社区

个人介绍

擅长的技术

HTTP基准压测工具wrk使用指南

给gRPC-spring-boot-starter一个pr的说明

集成apollo动态日志，“消灭”logback-spring.xml

spring boot应用优化，6s内启动，内存减半

解决apollo的configService服务启动异常

Feign-hystrix的配置，有了Apollo，还用Archaius吗？

Swagger异常定位纪实，是用的不对，还是Swagger本身设计问题

HTTP基准压测工具wrk使用指南

给gRPC-spring-boot-starter一个pr的说明

集成apollo动态日志，“消灭”logback-spring.xml

spring boot应用优化，6s内启动，内存减半

解决apollo的configService服务启动异常

Feign-hystrix的配置，有了Apollo，还用Archaius吗？

Swagger异常定位纪实，是用的不对，还是Swagger本身设计问题

HTTP基准压测工具wrk使用指南

给gRPC-spring-boot-starter一个pr的说明

集成apollo动态日志，“消灭”logback-spring.xml

spring boot应用优化，6s内启动，内存减半

[@古散][¥20]java现在用的比较多的持久层框架是哪个？