开发札记：如何在业务中添加日志系统

站长

2024年03月14日 22:39 · 阅读数 6

提到日志，我们一般只会想到使用@Slf4j打印的日志，实际上我们系统中的日志还可以细分为系统日志、登录日志和操作日志。本文将讲述如何在SpringBoot中使用和开发这三种日志系统。

关键词：Logback、Slf4j、p6spy、AspectJ、SpringEvent、线程池、Async

这里我根据业务将日志简单分为三类：

系统日志：打印到控制台和log文件中。
登录日志：记录用户登录信息。
操作日志：记录后台操作过程。

系统日志

Logback日志框架

logback依赖： spring-boot-dependencies会内置logback-core依赖，不需要手动引入。

logback配置：

# 日志配置  
logging:  
  level:  
    cn.cagurzhan: @logging.level@  
    org.springframework: warn  
  config: classpath:logback-plus.xml

logback.level：配置每个包的日志级别。
- 如：cn.cagurzhan: @logging.level@（对应父pom的profile内的变量，对每一个级别如debug等配置logging.level标签，见下方）
logback.config：指定配置文件。

<profile>
	<id>dev</id>
	<properties>
		<!-- 环境标识，需要与配置文件的名称相对应 -->
		<profiles.active>dev</profiles.active>
		<logging.level>info</logging.level>
	</properties>
	<activation>
		<!-- 默认环境 -->
		<activeByDefault>true</activeByDefault>
	</activation>
</profile>

logback配置文件解释：

property：变量。
- log.path：日志持久化路径。
  - thread：线程
  - level：级别
  - logger：类路径
  - msg：打印消息
- console.log.pattern / log.pattern：格式化
appender：输出目的地，声明日志输出组件
- name：标识
- class：实现类
- encoder：编码器
- file：持久化文件名
- rollingPolicy：文件名格式、日志保存记录数
- filter：阈值过滤器，设置过滤级别
- 异步调用：
  - discardingThreshold：不丢失日志。默认>队列80%丢弃INFO及以下日志。
  - queueSize：队列大小。
root：引入日志输出组件

以下是我的logback配置文件分享。

<?xml version="1.0" encoding="UTF-8"?>  
<configuration>  
    <property name="log.path" value="./logs"/>  
    <property name="console.log.pattern"  
              value="%red(%d{yyyy-MM-dd HH:mm:ss}) %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{36}%n) - %msg%n"/>  
    <property name="log.pattern" value="%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n"/>  
  
    <!-- 控制台输出 -->  
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">  
        <encoder>            <pattern>${console.log.pattern}</pattern>  
            <charset>utf-8</charset>  
        </encoder>    </appender>  
    <!-- 控制台输出 -->  
    <appender name="file_console" class="ch.qos.logback.core.rolling.RollingFileAppender">  
        <file>${log.path}/sys-console.log</file>  
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  
            <!-- 日志文件名格式 -->  
            <fileNamePattern>${log.path}/sys-console.%d{yyyy-MM-dd}.log</fileNamePattern>  
            <!-- 日志最大 1天 -->  
            <maxHistory>1</maxHistory>  
        </rollingPolicy>        <encoder>            <pattern>${log.pattern}</pattern>  
            <charset>utf-8</charset>  
        </encoder>        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">  
            <!-- 过滤的级别 -->  
            <level>INFO</level>  
        </filter>    </appender>  
    <!-- 系统日志输出 -->  
    <appender name="file_info" class="ch.qos.logback.core.rolling.RollingFileAppender">  
        <file>${log.path}/sys-info.log</file>  
        <!-- 循环政策：基于时间创建日志文件 -->  
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  
            <!-- 日志文件名格式 -->  
            <fileNamePattern>${log.path}/sys-info.%d{yyyy-MM-dd}.log</fileNamePattern>  
            <!-- 日志最大的历史 60天 -->  
            <maxHistory>60</maxHistory>  
        </rollingPolicy>        <encoder>            <pattern>${log.pattern}</pattern>  
        </encoder>        <filter class="ch.qos.logback.classic.filter.LevelFilter">  
            <!-- 过滤的级别 -->  
            <level>INFO</level>  
            <!-- 匹配时的操作：接收（记录） -->  
            <onMatch>ACCEPT</onMatch>  
            <!-- 不匹配时的操作：拒绝（不记录） -->  
            <onMismatch>DENY</onMismatch>  
        </filter>    </appender>  
    <appender name="file_error" class="ch.qos.logback.core.rolling.RollingFileAppender">  
        <file>${log.path}/sys-error.log</file>  
        <!-- 循环政策：基于时间创建日志文件 -->  
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  
            <!-- 日志文件名格式 -->  
            <fileNamePattern>${log.path}/sys-error.%d{yyyy-MM-dd}.log</fileNamePattern>  
            <!-- 日志最大的历史 60天 -->  
            <maxHistory>60</maxHistory>  
        </rollingPolicy>        <encoder>            <pattern>${log.pattern}</pattern>  
        </encoder>        <filter class="ch.qos.logback.classic.filter.LevelFilter">  
            <!-- 过滤的级别 -->  
            <level>ERROR</level>  
            <!-- 匹配时的操作：接收（记录） -->  
            <onMatch>ACCEPT</onMatch>  
            <!-- 不匹配时的操作：拒绝（不记录） -->  
            <onMismatch>DENY</onMismatch>  
        </filter>    </appender>  
    <!-- info异步输出 -->  
    <appender name="async_info" class="ch.qos.logback.classic.AsyncAppender">  
        <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->  
        <discardingThreshold>0</discardingThreshold>  
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->  
        <queueSize>512</queueSize>  
        <!-- 添加附加的appender,最多只能添加一个 -->  
        <appender-ref ref="file_info"/>  
    </appender>  
    <!-- error异步输出 -->  
    <appender name="async_error" class="ch.qos.logback.classic.AsyncAppender">  
        <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->  
        <discardingThreshold>0</discardingThreshold>  
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->  
        <queueSize>512</queueSize>  
        <!-- 添加附加的appender,最多只能添加一个 -->  
        <appender-ref ref="file_error"/>  
    </appender>  
  
    <!--系统操作日志-->  
    <root level="info">  
        <appender-ref ref="console" />  
        <appender-ref ref="async_info" />  
        <appender-ref ref="async_error" />  
        <appender-ref ref="file_console" />  
<!--        <appender-ref ref="sky_log"/>-->  
    </root>  
  
</configuration>

Slf4j

日志打印方式一：Logger工厂（单例模式）

Logger logger = LoggerFactory.getLogger("要记录的类");
logger.trace("xxx");
logger.info("xxx");
logger.debug("xxx");
logger.warn("xxx");
logger.error("xxx");

日志级别：

trace < debug < info < warn < error
只会打印级别大于等于已设置级别的日志

日志打印方式二：注解

类注解：@Slf4j
@Slf4j会自动生成一个log的logger单例。直接调用log.xxx即可。
- log.info("xxx,{},{}","xx","xx")
- log.info("xxx",exception)

SQL性能分析：p6spy

依赖：

<!-- sql性能分析插件 -->  
<dependency>  
    <groupId>p6spy</groupId>  
    <artifactId>p6spy</artifactId>  
    <version>${p6spy.version}</version>  
</dependency>

配置：

dev环境：spring.datasource.dynamic.p6spy=true
prod环境：不推荐开启

p6spy实现方式（了解）：代理多数据源，重写数据库connect方法，创建监听器，执行打印并统计时间。

旧模式（驱动代理）：在数据源层级开启代理，监听SQL语句执行，统计时间。
- 将driveClassName的com.mysql.cj.jdbc.Driver替换为P6SpyDriver（实现了Driver接口），监听SQL，拦截SQL统计时间后转发给JDBC的驱动。
- url也要变成：jdbc:p6spy:mysql
现在的模式：代理多数据源

配置文件解释：

modulelist：配置MybatisPlusLogFactory的扩展，启用监听。
logMessageFormat：也是Mp的实现，自定义日志打印
appender：也是Mp的实现，输出到控制台（StdoutLogger）
excludecategories：排除结果集
outagedetection：开启慢SQL记录，超过2S就记录
filter：开启过滤
exclude：过滤掉SELECT 1（用于数据库存活检测）

配置文件分享：

 # p6spy 性能分析插件配置文件  
modulelist=com.baomidou.mybatisplus.extension.p6spy.MybatisPlusLogFactory,com.p6spy.engine.outage.P6OutageFactory  
# 自定义日志打印  
logMessageFormat=com.baomidou.mybatisplus.extension.p6spy.P6SpyLogger  
#日志输出到控制台  
appender=com.baomidou.mybatisplus.extension.p6spy.StdoutLogger  
# 使用日志系统记录 sql#appender=com.p6spy.engine.spy.appender.Slf4JLogger  
# 设置 p6spy driver 代理  
#deregisterdrivers=true  
# 取消JDBC URL前缀  
useprefix=true  
# 配置记录 Log 例外,可去掉的结果集有error,info,batch,debug,statement,commit,rollback,result,resultset.  
excludecategories=info,debug,result,commit,resultset  
# 日期格式  
dateformat=yyyy-MM-dd HH:mm:ss  
# SQL语句打印时间格式  
databaseDialectTimestampFormat=yyyy-MM-dd HH:mm:ss  
# 实际驱动可多个  
#driverlist=org.h2.Driver  
# 是否开启慢SQL记录  
outagedetection=true  
# 慢SQL记录标准 2 秒  
outagedetectioninterval=2  
# 是否过滤 Logfilter=true  
# 过滤 Log 时所排除的 sql 关键字，以逗号分隔  
exclude=SELECT 1

登录日志实战

SpringEvent事件监听

发布事件：

注入ApplicationContext
在domain内新建一个Event事件类
实例化事件类，调用context.publishEvent(event)发布。

当然，也可以用封装的SpringUtils来发布事件。

创建监听器：

新建EventListener监听器类，注入容器。
新增方法，参数接收事件类，并加上@EventListener注解

例如：

@Async  
@EventListener  
public void recordOper(OperLogEvent operLogEvent) {  
    SysOperLog operLog = BeanUtil.toBean(operLogEvent, SysOperLog.class);  
    // 远程查询操作地点  
    operLog.setOperLocation(AddressUtils.getRealAddressByIP(operLog.getOperIp()));  
    insertOperlog(operLog);  
}

SpringEvent默认是同步的，是同一个线程内进行发布和监听。 如果监听器抛出异常，那么发布事件后面的代码不会执行。

多个监听器：

在同一个线程中执行，但是执行顺序不固定。如果要增加顺序，需要加上@Order(1)注解，越小越靠前执行。同步才能控制顺序，如果前面顺序的监听器抛出异常，后面的都不会执行！
缺点：同步监听用来记录日志等就会影响响应时间，影响用户体验！

异步监听：

实现：给监听器的方法加上@Async注解
做个小实验，得到这个加了注解的线程名：schedule-pool-1，响应时间也减少了。而且抛出异常不会影响其它监听器。

实验2：给加了@Async注解的监听器，通过缓存获取登录用户。实验结果：加了@Async注解的监听器无法从缓存拿到登录用户。

所以，需要通过异步拿到登录用户，最好在发布前存到Event里面！

实验3：发布事件方法加@Transactional注解，发布事件前增删数据库，然后发布事件，然后抛出异常。实验结果：事务会回滚，监听方法也执行了。

这并不意外，因为是同步执行的。 那如何做到事务提交了才执行监听呢？

将@EventListener注解改成：@TransactionalEventListener
- 默认phase=aftercommit
- 还有afterrollback等周期，可以根据不同需求来设计。
观察到实验结果符合预期，监听器的方法没有执行。

登录日志功能

登录日志功能：记录了每个用户的访问编号、用户名、登录地址、登录地点、浏览器、操作系统、登录状态、操作信息和登录日期等。

具体实践：

创建发布登录事件方法，传入username、status、msg、request。
1. 传入request是因为监听器是异步的，无法获取当前request。
在checkLogin、validated、login、logout等调用发布事件方法，记录登录成功、登录失败等事件的日志。
在服务层添加登录事件监听器，使用@Async注解保证异步调用。具体实现如下：
1. 从request拿到UserAgent、IP、address等信息。
2. 用StringBuilder拼接，输出到日志。
3. 创建SysLoginInfo对象，set属性，存入数据库。

操作日志实战

操作日志功能：操作日志记录包含系统模块、操作类型、请求方式、操作人员、操作地址、操作状态、操作日期、请求参数、返回参数等信息。

自定义@Log注解

@Log注解包含的内容：

操作的模块：如账户解锁、用户管理、字典管理等等。
操作的类型：如导入、导出、清空数据、其它等等。
操作人员
是否保存请求参数和响应参数
排除指定的请求参数，如password字段等。

@Target({ElementType.METHOD,ElementType.PARAMETER})  
@Retention(RetentionPolicy.RUNTIME)  
@Documented  
public @interface Log {  
    /**  
     * 模块  
     */  
    String title() default "";  
  
    /**  
     * 操作类型
     */  
    BusinessType businessType() default BusinessType.OTHER;  
  
    /**  
     * 操作人类别  
     */  
    OperatorType operatorType() default OperatorType.MANAGE;  
  
    /**  
     * 是否保存请求的参数  
     */  
    boolean isSaveRequestData() default true;  
  
    /**  
     * 是否保存响应的参数  
     */  
    boolean isSaveResponseData() default true;  
  
    /**  
     * 排除指定的请求参数  
     */  
    String[] excludeParamNames() default {};  
  
}

具体使用：

@Log(title = "测试单表", businessType = BusinessType.EXPORT)

LogAspect切面注解

定义一个切面：给类加上@Aspect注解，表示一个切面。切面可以包含多种类型通知。

@Slf4j  
@Aspect  
@Component  
public class LogAspect {

}

定义一个后置通知：使用@AfterReturning指定方法执行后运行，使用pointcut定义切点为我们自定义的@Log注解，使用returning指定接收返回值。

@AfterReturning(pointcut = "@annotation(controllerLog)", returning = "jsonResult")  
public void doAfterReturning(JoinPoint joinPoint, Log controllerLog, Object jsonResult) {  
    handleLog(joinPoint, controllerLog, null, jsonResult);  
}

定义拦截异常操作：使用@AfterThrowing注解，同样定义切点和抛出的异常

@AfterThrowing(value = "@annotation(controllerLog)", throwing = "e")  
public void doAfterThrowing(JoinPoint joinPoint, Log controllerLog, Exception e) {  
    handleLog(joinPoint, controllerLog, e, null);  
}

简单实现一个记录操作日志的功能handleLog：

创建日志对象OperLogEvent（具体的操作日志字段可以由业务而定义）
通过ServletUtils，获取客户端IP和其它请求信息，设置到OperLogEvent。
将异常状态和错误消息设置到OperLogEvent。
使用joinPoint连接点拿到方法名和类名
- String className = joinPoint.getTarget().getClass().getName();
- String methodName = joinPoint.getSignature().getName();
获取注解的描述信息，
使用SpringEvent发布事件，异步将OperLogEvent保存到数据库。

recordOper监听器：

使用了@Async和@EventListener实现异步日志记录。
使用Bean工具类，将OperLogEvent转为SysOperLo，插入数据库

注意事项：如果我们在log切面的处理方法中，使用了Sa-Token上下文来获取操作用户，而加了@Log的接口却是放行的，无法获取用户，就会抛出NPE。所以，@Log注解只能加在需要鉴权的接口上。

ServletUtils的原理：从当前线程上下文中拿到HttpServletRequest和HttpSevletResponse，如果是异步的，就获取不到。

线程池和Async注解

JUC线程池执行器：ThreadPoolExecutor，有七个参数的构造方法，分别是

核心线程数
最大线程数
空闲时间
时间单位
队列
线程工厂
拒绝策略

线程池执行流程：

发布任务，提交到线程池。
判断核心线程数是否已满，如果不是，创建核心线程池执行任务。
如果是，判断线程池队列数是否已满，如果不是，就将任务放到队列等待处理。
如果是，判断最大线程数是否已满，如果不是，创建非核心线程处理任务。如果是，按照拒绝策略执行任务（如拒绝任务、丢弃任务、将任务返回给主线程执行）
如果非核心线程处理任务处理完成，且空闲时间达到设置的时间，非核心线程就会进行销毁。

线程的状态：

RUNNING：正常接收任务
SHUTDOWN：调用shutdown()方法，不接受新任务，可以处理阻塞队列任务。
STOP：调用shutdownNow()，停止状态，不接受任务，不处理队列任务，终止正在工作的线程。
TIDYING：过渡态，当队列为空且工作线程为空会进入。
TERMINATED：terminated()会进入终止状态

线程池配置

ThreadPoolProperties配置类：设置是否开启线程池、队列最大数、线程池维护线程的空闲时间。

@Data  
@Component  
@ConfigurationProperties(prefix = "thread-pool")  
public class ThreadPoolProperties {  
    /**  
     * 是否开启线程池  
     */  
    private boolean enabled;  
    /**  
     * 队列最大长度  
     */  
    private int queueCapacity;  
    /**  
     * 线程池维护线程所允许的空闲时间  
     */  
    private int keepAliveSeconds;  
}

线程池配置

配置线程池核心数为CPU核心数+1
注入ThreadPoolTaskExecutor（springframework包下的），里面封装了JUC的ThreadPoolExecutor
- 注意：配置了@ConditionalOnProperty，所以只有当配置了enable开启才会注入。
- 设置核心数、队列数、队列容量、空闲时间、拒绝策略
注入ScheduledExecutorService，用于执行周期性或定时任务
- 命名规则：schedule-pool-%d
- 配置策略为调用者执行策略。
- Async注解就是使用这个线程池。

@Configuration  
public class ThreadPoolConfig {  
  
    /**  
     * 核心线程数 = cpu 核心数 + 1  
     */    private final int core = Runtime.getRuntime().availableProcessors() + 1;  
  
    @Autowired  
    private ThreadPoolProperties threadPoolProperties;  
  
    @Bean(name = "threadPoolTaskExecutor")  
    @ConditionalOnProperty(prefix = "thread-pool", name = "enabled", havingValue = "true")  
    public ThreadPoolTaskExecutor threadPoolTaskExecutor() {  
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();  
        executor.setCorePoolSize(core);  
        executor.setMaxPoolSize(core * 2);  
        executor.setQueueCapacity(threadPoolProperties.getQueueCapacity());  
        executor.setKeepAliveSeconds(threadPoolProperties.getKeepAliveSeconds());  
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());  
        return executor;  
    }  
  
    /**  
     * 执行周期性或定时任务  
     */  
    @Bean(name = "scheduledExecutorService")  
    protected ScheduledExecutorService scheduledExecutorService() {  
        return new ScheduledThreadPoolExecutor(core,  
            new BasicThreadFactory.Builder().namingPattern("schedule-pool-%d").daemon(true).build(),  
            new ThreadPoolExecutor.CallerRunsPolicy()) {  
            @Override  
            protected void afterExecute(Runnable r, Throwable t) {  
                super.afterExecute(r, t);  
                Threads.printException(r, t);  
            }  
        };  
    }  
}

使用线程池

注入线程池：private final ThreadPoolTaskExecutor executor
使用线程池执行方法：executor.submit(()->{})

class ThreadPoolController{
	// 注入线程池
	private final ThreadPoolTaskExecutor executor

	// 观察到，响应时间只有60ms，异步执行了method方法。
	public String pool2(){
		Future<String> submit = executor.submit(()->{
			this->method();
			return "hello";
		})
		String value = submit.get();
			log.info(value);
	}

	private void method(){
		ThreadUtils.sleep(3000);
	}
}

Async异步调用注解

创建配置类：

开启Async调用@EnableAsync(proxyTargetClass = true) ，并设置为cglib动态代理。
注入ScheduledExecutorService
提供异步执行器：scheduledExecutorService，即计划执行器。
提供异步未捕获异常处理器：AsyncUncaughtExceptionHandler

@EnableAsync(proxyTargetClass = true)  
@Configuration  
public class AsyncConfig extends AsyncConfigurerSupport {  
  
    @Autowired  
    @Qualifier("scheduledExecutorService")  
    private ScheduledExecutorService scheduledExecutorService;  
  
    /**  
     * 自定义 @Async 注解使用系统线程池  
     */  
    @Override  
    public Executor getAsyncExecutor() {  
        return scheduledExecutorService;  
    }  
  
    /**  
     * 异步执行异常处理  
     */  
    @Override  
    public AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {  
        return (throwable, method, objects) -> {  
            throwable.printStackTrace();  
            StringBuilder sb = new StringBuilder();  
            sb.append("Exception message - ").append(throwable.getMessage())  
                .append(", Method name - ").append(method.getName());  
            if (ArrayUtil.isNotEmpty(objects)) {  
                sb.append(", Parameter value - ").append(Arrays.toString(objects));  
            }  
            throw new ServiceException(sb.toString());  
        };  
    }  
  
}

使用：给方法加上Async注解。

注意事项：

直接使用内部调用方法无法生效，还是同一个线程。必须让方法交给Spring管理。因此，我们可以通过创建AsyncService，注入Spring容器，调用此类的@Async方法即可。
如果我们调用的AsyncService内的非Async方法，即使该方法内部调用了@Async方法（直接调用），那么仍然是通过单一线程进行执行的。所以，我们需要在主线程需要直接调用的方法上加入@Async。

异常：

主线程抛出异常不会影响子线程的方法执行。
子线程抛出异常不会影响主线程的方法执行。

事务：在不同线程中，事务管理是完全独立的。主线程的异常不影响子线程的事务提交，子线程的异常不影响主线程的事务提交。

开发札记：如何在业务中添加日志系统

系统日志

Logback日志框架

Slf4j

SQL性能分析：p6spy

登录日志实战

SpringEvent事件监听

登录日志功能

操作日志实战

自定义@Log注解

LogAspect切面注解

线程池和Async注解

线程池配置

使用线程池

Async异步调用注解

参考文章