日志级别动态调整——小工具解决大问题
NovellaFowl
8年前
<h2>背景</h2> <p>随着外卖业务的快速发展，业务复杂度不断增加，线上系统环境有任何细小波动，对整个外卖业务都可能产生巨大的影响，甚至形成灾难性的雪崩效应，造成巨大的经济损失。每一次客诉、系统抖动等都是对技术人员的重大考验，我们必须立即响应，快速解决问题。</p> <p>如何提高排查问题的效率呢？最有效的方式是通过分析系统日志。如果系统日志全面，会为我们排查解决线上问题带来绝大的帮助，但是要想保证系统日志全面，就必须打印出所有的系统或业务日志。这样就会带来另一个问题，那就是日志量的暴涨，过多的日志除了能够帮助我们解决问题外，同时会直接造成系统性能下降，极端情况下，甚至导致系统宕机。在这种背景下，为了兼顾性能和快速响应线上问题，我们设计开发了日志级别动态调整组件。通过使用该组件，可以在需要解决线上问题时，实时调整线上日志输出级别，获取全面的Debug日志，帮助工程师提高定位问题的效率。</p> <h2>简介</h2> <h3>使用场景</h3> <h3>场景一</h3> <p>业务依赖复杂。某一时刻，依赖的下游服务故障，导致请求大量超时，尤其是像外卖这种集中性特别明显的业务，平均每秒QPS在8000以上，1分钟的故障就会集中产生大量的错误日志，导致磁盘IO急剧提高，耗费大量CPU，进而导致整个服务瘫痪。如果该业务不能立即降级，怎么办？</p> <p>从代码级别解决问题到发版上线，暂且不说流程长、操作麻烦，同时还存在引入其它故障的高风险。如果系统恰好使用Log4j版本，在极短时间内打印出了海量错误日志，会快速耗尽Buffer区内存，从而拖慢主线程，造成服务性能整体下降，甚至还没有来得及修复问题，海量日志已经拖垮服务，造成服务宕机，损失惨重。</p> <h3>场景二</h3> <p>大量的订单、结算等客诉问题反馈过来，一线工程师大量精力埋没于排查问题中，而排查定位问题的最终手段仍然是依赖线上日志。由于链路较长，任一日志的缺失，都给问题的排查带来极大的障碍，面对运营的催促，怎么办？</p> <p>工程师为了以后排查问题的方便，在任一可能出现异常的地方，都会打印出关键日志，然后发版上线。但好不容易解决了本次问题，还没来得及收获喜悦，就又面临着一个新问题，那就是场景三。</p> <h3>场景三</h3> <p>由于线上业务系统默认日志打印级别是INFO级别，为了排查问题方便，调试型日志都以该级别打印出来。这样的话给系统带来了额外的负担，在高峰期大量调试日志时会拖慢系统性能，增大出故障的风险，怎么办？</p> <p>一方面要快速响应业务，另一方面要兼顾系统性能，能不能两方面兼顾？我们的动态调整日志级别工具正是为了解决这种痛点。</p> <h3>能解决哪些问题</h3> <ol> <li><strong>日志降级。</strong> 兼容Log4j、Log4j2和Logback主流日志框架，如果遇到场景一，可以通过我们的日志工具，快速调整日志输出级别，降低系统日志的输出，从而达到日志降级的效果，同时能够给RD争取充裕的排查问题时间。</li> <li><strong>规范日志级别滥用，帮助工程师快速定位解决线上问题。</strong> 使用日志级别动态调整组件，可以实时动态调整线上服务的日志打印级别，调试型日志可以使用低级别打印出，减轻线上服务的负载压力。遇到排查问题时，可以临时将日志级别调低，快速得到精准化的日志信息，排查解决问题。</li> </ol> <h2>系统基础架构</h2> <p>日志级别动态调整组件定位为中间件，在设计之初重点考虑了以下几点：</p> <ol> <li> <p>低侵入性</p> <ul> <li>接入服务仅需要引入JAR包和XML配置文件即可，不存在额外编码工作，业务耦合低、接入成本小。</li> </ul> </li> <li> <p>安全可靠</p> <ul> <li>更改接入服务的日志输出级别，只能通过我们提供的管理系统，所有的操作记录有迹可查。</li> <li>引入权限认证，确保工程师只能操作自己负责的服务或系统，同时会把操作内容实时周知给系统的所有相关责任人，避免误伤。</li> </ul> </li> <li> <p>可视化操作</p> <ul> <li>操作者可以通过我们提供的管理页面，定向修改一个或一批服务节点。</li> <li>提供可视化的操控开关，可以随时关闭或开启服务。</li> </ul> </li> </ol> <p><img src="https://simg.open-open.com/show/99f3a0891b1cdb7fb853d716ffe51e1c.png"></p> <h2>具体实现</h2> <h2>调用组件</h2> <p>本组件采用工厂模式实现，保障其高可扩展性。目前已实现日志级别动态调整和方法调用处理单元，下面主要介绍日志级别动态调整处理单元的实现。</p> <p><img src="https://simg.open-open.com/show/50278ff5a4d9a4de5aac4b0cf4db0de3.png"></p> <p>目前美团外卖业务系统基本统一采用的SLF4J日志框架，在应用初始化时，SLF4J会绑定具体的日志框架，如Log4j、Logback或Log4j2等。具体源码如下(slf4j-api-1.7.7)：</p> <pre> <code class="language-java">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(); ... }</code></pre> <p>findPossibleStaticLoggerBinderPathSet方法用来查找当前classpath下所有的org.slf4j.impl.StaticLoggerBinder类。每一个slf4j桥接包中都有一个StaticLoggerBinder类，该类实现了LoggerFactoryBinder接口。具体绑定到哪一个日志框架则取决于类加载顺序。</p> <p>接下来，咱们分三部分，来说说ChangeLogLevelProcessUnit类：</p> <ol> <li> <p>初始化：确定所使用的日志框架，获取配置文件中所有的Logger内存实例，并将它们的引用缓存到Map容器中。</p> <pre> <code class="language-java">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); }</code></pre> </li> <li> <p>获取Logger列表：从本地Map容器取出。</p> <pre> <code class="language-java">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(); }</code></pre> </li> <li> <p>修改Logger的级别。</p> <pre> <code class="language-java">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"; }</code></pre> </li> </ol> <p>上面介绍了如何拿到日志配置文件中的Logger，以及修改Logger的级别。</p> <h2>通信方式</h2> <p>我们根据Web项目和纯粹RPC项目，分别提供HTTP和Thrift两种通信协议。</p> <h3>场景一、Thrift服务</h3> <p>所有的请求信息都包含在JSON String的数据结构里面，其中包含有签名信息，请求时签名验证失败将直接抛出异常。</p> <p>引入组件提供的dynamic-invoker.xml配置，将会在系统中自动注入开启一个专为日志级别调整的接口服务，该接口是一个单纯的Thrift服务，能够通过ZooKeeper实现服务注册与发现，并且有可视化的开启与关闭管理后台，简单明了，操作方便。</p> <h3>场景二、HTTP服务</h3> <p>对于一些Web项目，暴露一个RPC服务相当不安全。为此，我们提供了HTTP协议接口，接入流程完全一样，在真正修改日志输出级别时，会根据系统类型自主判断使用哪种协议，有独立实现的签名认证，安全可靠。</p> <h2>结束语</h2> <p>从2016年9月V1.0版本上线以来，陆续接入外卖配送的20多个核心应用，覆盖推送、接单、配送调度、斑马配送、活动等核心交易服务。</p> <p>举例：</p> <ul> <li> <p>问题描述：发配送服务化项目由于间接依赖，引入了Logback日志框架。在项目启动加载时，SLF4J动态绑定到Logback框架上，但是由于发配送项目使用的Log4j，并未配置Logback.xml文件，导致在打印日志时，SLF4J无法匹配到具体的日志配置，从而为项目自动创建了一个日志级别为Debug的ROOT节点，所有的日志以该级别打印输出，导致发配送服务化项目在中午11：30左右高峰期，短时间内打印过多的系统日志，引起Load飙高，重新修改发版上线已经来不及，如果不能立即解决，势必造成服务化宕机，损失非常严重。</p> </li> <li> <p>处理结果：使用我们这个日志工具，批量将服务化项目所有的日志输出级别调整为ERROR级别，大大减少了日志量的输出，给工程师留出充裕的的时间完美的解决了该问题，避免造成更大的系统故障。</p> </li> <li> <p>后记：更重要的是以该工具组件为切入点，帮助各业务系统逐渐规范系统日志使用，取得很好效果。</p> </li> </ul> <p>后续我们规划将其推广成为公司级别的工具，为越来越多的项目提供便利。</p> <p>欢迎感兴趣的同学与我们进一步交流。</p> <h2>参考文献</h2> <ol> <li><a href="/misc/goto?guid=4959737776328774478" rel="nofollow,noindex">Simple Logging Facade for Java (SLF4J)</a></li> <li><a href="/misc/goto?guid=4959737776422282073" rel="nofollow,noindex">Log4j 2 Architecture - Apache Log4j 2</a></li> <li><a href="/misc/goto?guid=4959650806175384725" rel="nofollow,noindex">Hash-based message authentication code - Wikipedia</a></li> </ol> <p> </p> <p>来自：http://tech.meituan.com/change_log_level.html</p> <p></p> <p> </p>