随着外卖业务的快速发展,业务复杂度不断增加,线上系统环境有任何细小波动,对整个外卖业务都可能产生巨大的影响,甚至形成灾难性的雪崩效应,造成巨大的经济损失。每一次客诉、系统抖动等都是对技术人员的重大考验,我们必须立即响应,快速解决问题。
如何提高排查问题的效率呢?最有效的方式是通过分析系统日志。如果系统日志全面,会为我们排查解决线上问题带来绝大的帮助,但是要想保证系统日志全面,就必须打印出所有的系统或业务日志。这样就会带来另一个问题,那就是日志量的暴涨,过多的日志除了能够帮助我们解决问题外,同时会直接造成系统性能下降,极端情况下,甚至导致系统宕机。在这种背景下,为了兼顾性能和快速响应线上问题,我们设计开发了日志级别动态调整组件。通过使用该组件,可以在需要解决线上问题时,实时调整线上日志输出级别,获取全面的 Debug 日志,帮助工程师提高定位问题的效率。
业务依赖复杂。某一时刻,依赖的下游服务故障,导致请求大量超时,尤其是像外卖这种集中性特别明显的业务,平均每秒 QPS 在 8000 以上,1 分钟的故障就会集中产生大量的错误日志,导致磁盘 IO 急剧提高,耗费大量 CPU,进而导致整个服务瘫痪。如果该业务不能立即降级,怎么办?
从代码级别解决问题到发版上线,暂且不说流程长、操作麻烦,同时还存在引入其它故障的高风险。如果系统恰好使用 Log4j 版本,在极短时间内打印出了海量错误日志,会快速耗尽 Buffer 区内存,从而拖慢主线程,造成服务性能整体下降,甚至还没有来得及修复问题,海量日志已经拖垮服务,造成服务宕机,损失惨重。
大量的订单、结算等客诉问题反馈过来,一线工程师大量精力埋没于排查问题中,而排查定位问题的最终手段仍然是依赖线上日志。由于链路较长,任一日志的缺失,都给问题的排查带来极大的障碍,面对运营的催促,怎么办?
工程师为了以后排查问题的方便,在任一可能出现异常的地方,都会打印出关键日志,然后发版上线。但好不容易解决了本次问题,还没来得及收获喜悦,就又面临着一个新问题,那就是场景三。
由于线上业务系统默认日志打印级别是 INFO 级别,为了排查问题方便,调试型日志都以该级别打印出来。这样的话给系统带来了额外的负担,在高峰期大量调试日志时会拖慢系统性能,增大出故障的风险,怎么办?
一方面要快速响应业务,另一方面要兼顾系统性能,能不能两方面兼顾?我们的动态调整日志级别工具正是为了解决这种痛点。
日志级别动态调整组件定位为中间件,在设计之初重点考虑了以下几点:
本组件采用工厂模式实现,保障其高可扩展性。目前已实现日志级别动态调整和方法调用处理单元,下面主要介绍日志级别动态调整处理单元的实现。
目前美团外卖业务系统基本统一采用的 SLF4J 日志框架,在应用初始化时,SLF4J 会绑定具体的日志框架,如 Log4j、Logback 或 Log4j2 等。具体源码如下 (slf4j-api-1.7.7):
- private final static void bind() {
- try {
- // 查找classpath下所有的StaticLoggerBinder类。
- Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
- reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
- // 每一个slf4j桥接包中都有一个org.slf4j.impl.StaticLoggerBinder类,该类实现了LoggerFactoryBinder接口。
- // the next line does the binding
- StaticLoggerBinder.getSingleton();
- INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
- reportActualBinding(staticLoggerBinderPathSet);
- fixSubstitutedLoggers();
- ...
- }
findPossibleStaticLoggerBinderPathSet 方法用来查找当前 classpath 下所有的 org.slf4j.impl.StaticLoggerBinder 类。每一个 slf4j 桥接包中都有一个 StaticLoggerBinder 类,该类实现了 LoggerFactoryBinder 接口。具体绑定到哪一个日志框架则取决于类加载顺序。
接下来,咱们分三部分,来说说 ChangeLogLevelProcessUnit 类:
- String type = StaticLoggerBinder.getSingleton().getLoggerFactoryClassStr();
- if (LogConstant.LOG4J_LOGGER_FACTORY.equals(type)) {
- logFrameworkType = LogFrameworkType.LOG4J;
- Enumeration enumeration = org.apache.log4j.LogManager.getCurrentLoggers();
- while (enumeration.hasMoreElements()) {
- org.apache.log4j.Logger logger = (org.apache.log4j.Logger) enumeration.nextElement();
- if (logger.getLevel() != null) {
- loggerMap.put(logger.getName(), logger);
- }
- }
- org.apache.log4j.Logger rootLogger = org.apache.log4j.LogManager.getRootLogger();
- loggerMap.put(rootLogger.getName(), rootLogger);
- } else if (LogConstant.LOGBACK_LOGGER_FACTORY.equals(type)) {
- logFrameworkType = LogFrameworkType.LOGBACK;
- ch.qos.logback.classic.LoggerContext loggerContext = (ch.qos.logback.classic.LoggerContext) LoggerFactory.getILoggerFactory();
- for (ch.qos.logback.classic.Logger logger: loggerContext.getLoggerList()) {
- if (logger.getLevel() != null) {
- loggerMap.put(logger.getName(), logger);
- }
- }
- ch.qos.logback.classic.Logger rootLogger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
- loggerMap.put(rootLogger.getName(), rootLogger);
- } else if (LogConstant.LOG4J2_LOGGER_FACTORY.equals(type)) {
- logFrameworkType = LogFrameworkType.LOG4J2;
- org.apache.logging.log4j.core.LoggerContext loggerContext = (org.apache.logging.log4j.core.LoggerContext) org.apache.logging.log4j.LogManager.getContext(false);
- Map < String,
- org.apache.logging.log4j.core.config.LoggerConfig > map = loggerContext.getConfiguration().getLoggers();
- for (org.apache.logging.log4j.core.config.LoggerConfig loggerConfig: map.values()) {
- String key = loggerConfig.getName();
- if (StringUtils.isBlank(key)) {
- key = "root";
- }
- loggerMap.put(key, loggerConfig);
- }
- } else {
- logFrameworkType = LogFrameworkType.UNKNOWN;
- LOG.error("Log框架无法识别: type={}", type);
- }
- private String getLoggerList() {
- JSONObject result = new JSONObject();
- result.put("logFramework", logFrameworkType);
- JSONArray loggerList = new JSONArray();
- for (ConcurrentMap.Entry<String, Object> entry : loggerMap.entrySet()) {
- JSONObject loggerJSON = new JSONObject();
- loggerJSON.put("loggerName", entry.getKey());
- if (logFrameworkType == LogFrameworkType.LOG4J) {
- org.apache.log4j.Logger targetLogger = (org.apache.log4j.Logger) entry.getValue();
- loggerJSON.put("logLevel", targetLogger.getLevel().toString());
- } else if (logFrameworkType == LogFrameworkType.LOGBACK) {
- ch.qos.logback.classic.Logger targetLogger = (ch.qos.logback.classic.Logger) entry.getValue();
- loggerJSON.put("logLevel", targetLogger.getLevel().toString());
- } else if (logFrameworkType == LogFrameworkType.LOG4J2) {
- org.apache.logging.log4j.core.config.LoggerConfig targetLogger = (org.apache.logging.log4j.core.config.LoggerConfig) entry.getValue();
- loggerJSON.put("logLevel", targetLogger.getLevel().toString());
- } else {
- loggerJSON.put("logLevel", "Logger的类型未知,无法处理!");
- }
- loggerList.add(loggerJSON);
- }
- result.put("loggerList", loggerList);
- LOG.info("getLoggerList: result={}", result.toString());
- return result.toString();
- }
- private String setLogLevel(JSONArray data) {
- LOG.info("setLogLevel: data={}", data);
- List<LoggerBean> loggerList = parseJsonData(data);
- if (CollectionUtils.isEmpty(loggerList)) {
- return "";
- }
- for (LoggerBean loggerbean : loggerList) {
- Object logger = loggerMap.get(loggerbean.getName());
- if (logger == null) {
- throw new RuntimeException("需要修改日志级别的Logger不存在");
- }
- if (logFrameworkType == LogFrameworkType.LOG4J) {
- org.apache.log4j.Logger targetLogger = (org.apache.log4j.Logger) logger;
- org.apache.log4j.Level targetLevel = org.apache.log4j.Level.toLevel(loggerbean.getLevel());
- targetLogger.setLevel(targetLevel);
- } else if (logFrameworkType == LogFrameworkType.LOGBACK) {
- ch.qos.logback.classic.Logger targetLogger = (ch.qos.logback.classic.Logger) logger;
- ch.qos.logback.classic.Level targetLevel = ch.qos.logback.classic.Level.toLevel(loggerbean.getLevel());
- targetLogger.setLevel(targetLevel);
- } else if (logFrameworkType == LogFrameworkType.LOG4J2) {
- org.apache.logging.log4j.core.config.LoggerConfig loggerConfig = (org.apache.logging.log4j.core.config.LoggerConfig) logger;
- org.apache.logging.log4j.Level targetLevel = org.apache.logging.log4j.Level.toLevel(loggerbean.getLevel());
- loggerConfig.setLevel(targetLevel);
- org.apache.logging.log4j.core.LoggerContext ctx = (org.apache.logging.log4j.core.LoggerContext) org.apache.logging.log4j.LogManager.getContext(false);
- ctx.updateLoggers(); // This causes all Loggers to refetch information from their LoggerConfig.
- } else {
- throw new RuntimeException("Logger的类型未知,无法处理!");
- }
- }
- return "success";
- }
上面介绍了如何拿到日志配置文件中的 Logger,以及修改 Logger 的级别。
我们根据 web 项目和纯粹 RPC 项目,分别提供 HTTP 和 Thrift 两种通信协议。
所有的请求信息都包含在 JSON String 的数据结构里面,其中包含有签名信息,请求时签名验证失败将直接抛出异常。
引入组件提供的 dynamic-invoker.xml 配置,将会在系统中自动注入开启一个专为日志级别调整的接口服务,该接口是一个单纯的 Thrift 服务,能够通过 ZooKeeper 实现服务注册与发现,并且有可视化的开启与关闭管理后台,简单明了,操作方便。
对于一些 Web 项目,暴露一个 RPC 服务相当不安全。为此,我们提供了 HTTP 协议接口,接入流程完全一样,在真正修改日志输出级别时,会根据系统类型自主判断使用哪种协议,有独立实现的签名认证,安全可靠。
从 2016 年 9 月 V1.0 版本上线以来,陆续接入外卖配送的 20 多个核心应用,覆盖推送、接单、配送调度、斑马配送、活动等核心交易服务。
举例:
后续我们规划将其推广成为公司级别的工具,为越来越多的项目提供便利。
欢迎感兴趣的同学与我们进一步交流。
来源: http://www.tuicool.com/articles/nE36Vn3