日志配置热更新技术实践

2023-02-27

name org jdbc

 一为什么需要服务日志热更新?对于后端老鸟来说，一定遇到过这样的场景：为了排查线上突发的问题，非常希望能够全面的看到请求在服务链路上的完整日志输出;But，在生产环境中，为了避免日志打印过量造成磁盘空间浪费，通常会将日志级别设定在INFO，并关闭一般情况用不到的日志输出;在不重启服务的情况

一为什么需要服务日志热更新?

对于后端老鸟来说，一定遇到过这样的场景：

为了排查线上突发的问题，非常希望能够全面的看到请求在服务链路上的完整日志输出;

But，在生产环境中，为了避免日志打印过量造成磁盘空间浪费，通常会将日志级别设定在INFO，并关闭一般情况用不到的日志输出;

在不重启服务的情况下，开启本已经关闭的业务日志输出，能不能搞的定呢?答案是当然没问题。

二需求分析

熟悉logback的同学此时肯定已经想到通过扫描监听logback.xml文件配置变化来实现日志级别的调整，像如下这种方式：

<configuration debug="true" scan="true" scanPeriod="1 seconds"> 
1.

但通常情况下，你的业务服务是分布式部署的，后端节点有多台，如果一台台的去改，且不说运维大哥未必就会同意给你生产机器文件的修改权限，即使可以，这么做未免有些过于“老实”了;有没有一种可以集中管理日志配置，修改文件后再逐个分发给各节点的解决方案呢?沿着这个思路，自然而然就会联想到配置中心，这里，我主要介绍携程开源的apollo，同类的配置中心产品还有百度Disconf、阿里ACM和Spring Cloud Config，感兴趣的自行研究。

三做实验

熟悉apollo文件管理的同学都知道，apollo通过推拉结合的方式将服务端存储的应用配置文件缓存到本地是以properties的格式存储的，如下面所示：

demo+dev+logback.xml.properties

content=<?xml version\="1.0" encoding\="UTF-8"?>\n<configuration debug\="true">\n\t<property name\="encoding" value\="UTF-8"/>\n\n\t<appender name\="STDOUT" class\="ch.qos.logback.core.ConsoleAppender">\n\t\t<encoder class\="ch.qos.logback.classic.encoder.PatternLayoutEncoder">\n\t\t\t<pattern>%d{yyyy-MM-dd HH\:mm\:ss.SSS}|%X{requestId}|[%t] %-5level %logger{50} %line - %m%n</pattern>\n\t\t</encoder>\n\t</appender>\n\n\t<appender name\="FILE" class\="ch.qos.logback.core.rolling.RollingFileAppender">\n\t\t<file>logs/brm.log</file>\n\t\t<encoder class\="ch.qos.logback.classic.encoder.PatternLayoutEncoder">\n\t\t\t<pattern>%d{yyyy-MM-dd HH\:mm\:ss.SSS}|%X{requestId}|%X{requestSeq}|[%t] %-5level %logger{50} %line - %m%n</pattern>\n\t\t</encoder>\n\t\t<rollingPolicy class\="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">\n\t\t\t<fileNamePattern>logs/brm-%d{yyyy-MM-dd-HH}-%i.log</fileNamePattern>>\n\t\t\t<\!--单个文件切割阈值，超过生成新log文件-->\n\t\t\t<maxFileSize>200MB</maxFileSize>\n\t\t\t<\!--最大保留天数-->\n\t\t\t<maxHistory>336</maxHistory>\n\t\t</rollingPolicy>\n\t</appender>\n\n    <\!--log4jdbc -->\n    <logger name\="jdbc.sqltiming" level\="INFO"/>\n    <logger name\="jdbc.sqlonly" level\="OFF"/>\n    <logger name\="jdbc.audit" level\="OFF"/>\n    <logger name\="jdbc.resultset" level\="OFF"/>\n    <logger name\="jdbc.resultsettable" level\="OFF"/>\n    <logger name\="jdbc.connection" level\="OFF"/>\n        \n\t<root level\="INFO">\n\t\t<appender-ref ref\="STDOUT"/>\n\t\t<appender-ref ref\="FILE"/>\n\t</root>\n</configuration> 
1.

HH\:mm\:ss.SSS}|%X{requestId}|%X{requestSeq}|[%t] %-5level %logger{50} %line - %m%n \n\t\t\n\t\t\n\t\t\tlogs/brm-%d{yyyy-MM-dd-HH}-%i.log>\n\t\t\t<\!--单个文件切割阈值，超过生成新log文件-->\n\t\t\t200MB\n\t\t\t<\!--最大保留天数-->\n\t\t\t336\n\t\t\n\t\n\n <\!--log4jdbc -->\n \n \n \n \n \n \n \n\t\n\t\t\n\t\t\n\t\n

而我们通常在配置logback的时候使用的是xml文件;

因此，我们要想办法让logback能够加载context的内存值信息。

阅读logback资料发现，JoranConfigurator支持我们以自定义的方式配置logback，

而springboot是通过LoggingSystem来加载管理日志系统的;如果我能在springboot启动的时候指定我自定义的日志加载类，问题便迎刃而解。

这里，我们在resources目录下新建META-INF文件夹，添加spring.factories，内容如下：

org.springframework.context.ApplicationContextInitializer = com.zhoupu.zplog.refresher.LoggerRefresher 
org.springframework.boot.env.EnvironmentPostProcessor = com.zhoupu.zplog.refresher.LoggerRefresher 
1.
2.

这里我们定义一个LoggerRefresher，该类重写loadDefaults和loadConfiguration方法，通过JoranConfigurator加载logback配置，并在configureByApollo中添加一个apollo事件监听器，当发现logback.xml文件有变化时，重新执行configureByApollo方法刷新日志配置。

核心代码部分如下：

package com.zhoupu.zplog.refresher; 
 
import ch.qos.logback.classic.LoggerContext; 
import ch.qos.logback.classic.joran.JoranConfigurator; 
import ch.qos.logback.core.joran.spi.JoranException; 
import com.ctrip.framework.apollo.Config; 
import com.ctrip.framework.apollo.ConfigChangeListener; 
import com.ctrip.framework.apollo.ConfigService; 
import com.ctrip.framework.apollo.model.ConfigChangeEvent; 
import com.ctrip.framework.apollo.spring.config.PropertySourcesConstants; 
import org.slf4j.ILoggerFactory; 
import org.slf4j.Logger; 
import org.slf4j.LoggerFactory; 
import org.springframework.boot.SpringApplication; 
import org.springframework.boot.env.EnvironmentPostProcessor; 
import org.springframework.context.ApplicationContextInitializer; 
import org.springframework.context.ConfigurableApplicationContext; 
import org.springframework.core.Ordered; 
import org.springframework.core.env.ConfigurableEnvironment; 
import org.springframework.util.StringUtils; 
 
import javax.xml.parsers.DocumentBuilder; 
import javax.xml.parsers.DocumentBuilderFactory; 
import java.io.ByteArrayInputStream; 
import java.io.UnsupportedEncodingException; 
 
/** 
 * 
 * @author vigor 
 * @date 2019/6/14 上午11:27 
 */ 
 
public class LoggerRefresher implements ApplicationContextInitializer<ConfigurableApplicationContext>, EnvironmentPostProcessor, Ordered { 
    private static final Logger log = LoggerFactory.getLogger(LoggerRefresher.class); 
 
    private boolean loadFlag = false; 
 
    @Override 
    public void initialize(ConfigurableApplicationContext context) { 
        ConfigurableEnvironment environment = context.getEnvironment(); 
        load(environment); 
 
    } 
 
    @Override 
    public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) { 
        load(environment); 
    } 
 
    @Override 
    public int getOrder() { 
        return 1; 
    } 
 
    private void load(ConfigurableEnvironment environment) { 
        if (!loadFlag) { 
            environment.getPropertySources().forEach(ps -> { 
                if (PropertySourcesConstants.APOLLO_BOOTSTRAP_PROPERTY_SOURCE_NAME.equals(ps.getName())) { 
                    configureByApollo(); 
                    loadFlag = true; 
                } 
            }); 
        } 
    } 
 
    private void configureByApollo() { 
        Config config = ConfigService.getConfig("logback.xml"); 
 
        String content = config.getProperty("content", ""); 
        if (StringUtils.isEmpty(content) || !validateXML(content)) { 
            return; 
        } 
 
        config.addChangeListener(new ConfigChangeListener() { 
            @Override 
            public void onChange(ConfigChangeEvent changeEvent) { 
                configureByApollo(); 
            } 
 
            @Override 
            public boolean equals(Object obj) { 
                if (this == obj) { 
                    return true; 
                } 
                if (this.getClass().equals(obj.getClass())) { 
                    return true; 
                } 
                return false; 
            } 
 
            @Override 
            public int hashCode() { 
                return 1; 
            } 
        }); 
 
        ILoggerFactory loggerFactory = LoggerFactory.getILoggerFactory(); 
        LoggerContext loggerContext = (LoggerContext) loggerFactory; 
        loggerContext.reset(); 
        JoranConfigurator configurator = new JoranConfigurator(); 
        configurator.setContext(loggerContext); 
        try { 
            configurator.doConfigure(new ByteArrayInputStream(content.getBytes("utf-8"))); 
            log.warn("*****************************logback configureByApollo success!********************************"); 
        } catch (JoranException e) { 
            e.printStackTrace(); 
        } catch (UnsupportedEncodingException e) { 
            e.printStackTrace(); 
        } 
    } 
 
    private boolean validateXML(String xml){ 
        boolean isValidated = true; 
        try { 
            DocumentBuilderFactory documentBuilderFactory = DocumentBuilderFactory.newInstance(); 
            DocumentBuilder builder = documentBuilderFactory.newDocumentBuilder(); 
            builder.parse(new ByteArrayInputStream(xml.getBytes("utf-8"))); 
        } catch (Exception e) { 
            log.error("apollo logback config error = {}", e); 
            isValidated = false; 
        } 
        return isValidated; 
    } 
 
} 
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
90.
91.
92.
93.
94.
95.
96.
97.
98.
99.
100.
101.
102.
103.
104.
105.
106.
107.
108.
109.
110.
111.
112.
113.
114.
115.
116.
117.
118.
119.
120.
121.
122.
123.
124.
125.

至此已完成所有准备工作，运行demo程序，我的项目使用log4jdbc输出sql，这里我通过修改apollo配置管理后台jdbc日志配置，将sqltiming级别改为INFO：

<!--log4jdbc --> 
    <logger name="jdbc.sqltiming" level="INFO"/> 
    <logger name="jdbc.sqlonly" level="OFF"/> 
    <logger name="jdbc.audit" level="OFF"/> 
    <logger name="jdbc.resultset" level="OFF"/> 
    <logger name="jdbc.resultsettable" level="OFF"/> 
    <logger name="jdbc.connection" level="OFF"/> 
1.
2.
3.
4.
5.
6.
7.

发起一个后端请求，查看控制台日志输出，有了!

2019-11-08 10:11:27.794|1fe97e7dcfeb4fc2810d8a7a706fad2a||[http-nio-8062-exec-3] INFO  jdbc.sqltiming 357 - SELECT id, row_state, created_at, updated_at, created_by, updated_by, business_id, contact_name, 
role, mobile, contact_type FROM t_business_contact WHERE row_state = 0 AND business_id = 1000006 
1.
2.

惊不惊喜_，意不意外!

四总结

一个简单的日志配置热更新尝试，串联起了logback的自定义配置加载原理，apollo的配置中心使用方法和事件监听机制，以及springboot日志管理和自动装配等知识点，希望大家能从中有所收获!

【本文是51CTO专栏机构“舟谱数据”的原创文章，微信公众号“舟谱数据( id: zhoupudata)”】

戳这里，看该作者更多好文