日志级别动态调整——小工具解决大问题

背景

随着外卖业务的快速发展,业务复杂度不断增加,线上系统环境有任何细小波动,对整个外卖业务都可能产生巨大的影响,甚至形成灾难性的雪崩效应,造成巨大的经济损失。每一次客诉、系统抖动等都是对技术人员的重大考验,我们必须立即响应,快速解决问题。

如何提高排查问题的效率呢?最有效的方式是通过分析系统日志。如果系统日志全面,会为我们排查解决线上问题带来绝大的帮助,但是要想保证系统日志全面,就必须打印出所有的系统或业务日志。这样就会带来另一个问题,那就是日志量的暴涨,过多的日志除了能够帮助我们解决问题外,同时会直接造成系统性能下降,极端情况下,甚至导致系统宕机。在这种背景下,为了兼顾性能和快速响应线上问题,我们设计开发了日志级别动态调整组件。通过使用该组件,可以在需要解决线上问题时,实时调整线上日志输出级别,获取全面的Debug日志,帮助工程师提高定位问题的效率。

简介

使用场景

场景一

业务依赖复杂。某一时刻,依赖的下游服务故障,导致请求大量超时,尤其是像外卖这种集中性特别明显的业务,平均每秒QPS在8000以上,1分钟的故障就会集中产生大量的错误日志,导致磁盘IO急剧提高,耗费大量CPU,进而导致整个服务瘫痪。如果该业务不能立即降级,怎么办?

从代码级别解决问题到发版上线,暂且不说流程长、操作麻烦,同时还存在引入其它故障的高风险。如果系统恰好使用Log4j版本,在极短时间内打印出了海量错误日志,会快速耗尽Buffer区内存,从而拖慢主线程,造成服务性能整体下降,甚至还没有来得及修复问题,海量日志已经拖垮服务,造成服务宕机,损失惨重。

场景二

大量的订单、结算等客诉问题反馈过来,一线工程师大量精力埋没于排查问题中,而排查定位问题的最终手段仍然是依赖线上日志。由于链路较长,任一日志的缺失,都给问题的排查带来极大的障碍,面对运营的催促,怎么办?

工程师为了以后排查问题的方便,在任一可能出现异常的地方,都会打印出关键日志,然后发版上线。但好不容易解决了本次问题,还没来得及收获喜悦,就又面临着一个新问题,那就是场景三。

场景三

由于线上业务系统默认日志打印级别是INFO级别,为了排查问题方便,调试型日志都以该级别打印出来。这样的话给系统带来了额外的负担,在高峰期大量调试日志时会拖慢系统性能,增大出故障的风险,怎么办?

一方面要快速响应业务,另一方面要兼顾系统性能,能不能两方面兼顾?我们的动态调整日志级别工具正是为了解决这种痛点。

能解决哪些问题

  1. 日志降级。 兼容Log4j、Log4j2和Logback主流日志框架,如果遇到场景一,可以通过我们的日志工具,快速调整日志输出级别,降低系统日志的输出,从而达到日志降级的效果,同时能够给RD争取充裕的排查问题时间。
  2. 规范日志级别滥用,帮助工程师快速定位解决线上问题。 使用日志级别动态调整组件,可以实时动态调整线上服务的日志打印级别,调试型日志可以使用低级别打印出,减轻线上服务的负载压力。遇到排查问题时,可以临时将日志级别调低,快速得到精准化的日志信息,排查解决问题。

系统基础架构

日志级别动态调整组件定位为中间件,在设计之初重点考虑了以下几点:

  1. 低侵入性
    • 接入服务仅需要引入JAR包和XML配置文件即可,不存在额外编码工作,业务耦合低、接入成本小。
  2. 安全可靠
    • 更改接入服务的日志输出级别,只能通过我们提供的管理系统,所有的操作记录有迹可查。
    • 引入权限认证,确保工程师只能操作自己负责的服务或系统,同时会把操作内容实时周知给系统的所有相关责任人,避免误伤。
  3. 可视化操作
    • 操作者可以通过我们提供的管理页面,定向修改一个或一批服务节点。
    • 提供可视化的操控开关,可以随时关闭或开启服务。

具体实现

调用组件

本组件采用工厂模式实现,保障其高可扩展性。目前已实现日志级别动态调整和方法调用处理单元,下面主要介绍日志级别动态调整处理单元的实现。

目前美团外卖业务系统基本统一采用的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类:

1. 初始化:确定所使用的日志框架,获取配置文件中所有的Logger内存实例,并将它们的引用缓存到Map容器中。

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);
}

2. 获取Logger列表:从本地Map容器取出。

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();
}

3. 修改Logger的级别。

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两种通信协议。

场景一、Thrift服务

所有的请求信息都包含在JSON String的数据结构里面,其中包含有签名信息,请求时签名验证失败将直接抛出异常。

引入组件提供的dynamic-invoker.xml配置,将会在系统中自动注入开启一个专为日志级别调整的接口服务,该接口是一个单纯的Thrift服务,能够通过ZooKeeper实现服务注册与发现,并且有可视化的开启与关闭管理后台,简单明了,操作方便。

场景二、HTTP服务

对于一些Web项目,暴露一个RPC服务相当不安全。为此,我们提供了HTTP协议接口,接入流程完全一样,在真正修改日志输出级别时,会根据系统类型自主判断使用哪种协议,有独立实现的签名认证,安全可靠。

结束语

从2016年9月V1.0版本上线以来,陆续接入外卖配送的20多个核心应用,覆盖推送、接单、配送调度、斑马配送、活动等核心交易服务。

举例:

  • 问题描述:发配送服务化项目由于间接依赖,引入了Logback日志框架。在项目启动加载时,SLF4J动态绑定到Logback框架上,但是由于发配送项目使用的Log4j,并未配置Logback.xml文件,导致在打印日志时,SLF4J无法匹配到具体的日志配置,从而为项目自动创建了一个日志级别为Debug的ROOT节点,所有的日志以该级别打印输出,导致发配送服务化项目在中午11:30左右高峰期,短时间内打印过多的系统日志,引起Load飙高,重新修改发版上线已经来不及,如果不能立即解决,势必造成服务化宕机,损失非常严重。
  • 处理结果:使用我们这个日志工具,批量将服务化项目所有的日志输出级别调整为ERROR级别,大大减少了日志量的输出,给工程师留出充裕的的时间完美的解决了该问题,避免造成更大的系统故障。
  • 后记:更重要的是以该工具组件为切入点,帮助各业务系统逐渐规范系统日志使用,取得很好效果。

后续我们规划将其推广成为公司级别的工具,为越来越多的项目提供便利。

欢迎感兴趣的同学与我们进一步交流。

参考文献

  1. Simple Logging Facade for Java (SLF4J)
  2. Log4j 2 Architecture - Apache Log4j 2
  3. Hash-based message authentication code - Wikipedia

原文发布于微信公众号 - 美团点评技术团队(meituantech)

原文发表时间:2017-02-17

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

1 条评论
登录 后参与评论

相关文章

来自专栏happyJared

爬虫进阶:Scrapy抓取boss直聘、拉勾心得经验

关于使用Scrapy的体会,最明显的感受就是这种模板化、工程化的脚手架体系,可以说是拿来即可开箱便用,大多仅需按一定的规则套路配置,剩下的就是专注于编写跟爬虫业...

652
来自专栏IT大咖说

探索嵌入式PHP与C/C++结合的无限种可能

内容来源:2018 年 5 月 20 日,腾讯企点开放平台技术负责人熊月在“PHPCon China 2018 技术峰会”进行《嵌入式PHP的探索实践》演讲分享...

1152
来自专栏Android 开发学习

2016年干货小结

1382
来自专栏北京马哥教育

Linux 多核下绑定硬件中断到不同 CPU

硬件中断发生频繁,是件很消耗 CPU 资源的事情,在多核 CPU 条件下如果有办法把大量硬件中断分配给不同的 CPU (core) 处理显然能很好的平衡性能。 ...

3207
来自专栏腾讯Bugly的专栏

【发布公告】您的应用卡么?Bugly全新功能:卡顿/ANR监控

亲爱的Bugly用户: 您好~ 腾讯Bugly于7月13日正式发布了 iOS卡顿、Android ANR(应用无响应)监控上报功能,业内只此一家,别无分店。 通...

2764
来自专栏Linyb极客之路

一位Java工程师的阶段性工作总结

1.1.1、通常的模块分布:一般如果你要实现一个web应用,你从后台将数据展示到前端页面,在一个比较大的公司,你少不了跟其他项目有交集(你调用他的接口,他依赖你...

823
来自专栏架构师之路

12306系统架构优化

12306系统架构优化 coolshell陈皓优化方案 原文:http://coolshell.cn/articles/6470.html 一、业务复杂度比对 ...

3894
来自专栏性能与架构

Spring 5 响应式开发

2044
来自专栏王亚昌的专栏

Go语言入门之路

Go is designed from first principles to advance the practice of software enginee...

2225
来自专栏王亚昌的专栏

Way to Go

Go is designed from first principles to advance the practice of software enginee...

692

扫码关注云+社区