iOS Developer的全栈之路 - log

说到服务端的日志，重要性不言而喻，追踪业务问题，监控Production环境下的性能（相比本地压测，监控真实环境的性能来的更为直接有效）。

SpringBoot为我们集成了日志框架Logback，当然也可以根据需要切换其他的日志框架，我们先从Logback开始吧。当我们没有做任何配置的情况下，已经可以在控制台看到日志的输出：

default log.png

这就是一个默认的配置输出，如果我们想对输出结果进行一些定制，比如输出到哪里，格式是什么样，输出什么level的日志。在resource目录下，添加一个名logback-spring.xml的配置文件，也可以选用如下的文件名：

• logback-spring.xml
• logback.xml
• logback-spring.groovy
• logback.groovy

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 这里定义了一个名为LOGS的变量 -->
    <property name="LOGS" value="./logs" />

    <!-- Console输出的方式 -->
    <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <!-- Console输出的格式 -->
            <Pattern>
                %black(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] %yellow(%C{1.}): %msg%n%throwable
            </Pattern>
        </layout>
    </appender>
    <!-- 日志输出的方式 -->
    <appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 日志输出到哪里，此处用了上面定义的LOGS变量-->
        <file>${LOGS}/spring-boot-logger.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!-- 日志输出的格式 -->
            <Pattern>%d %p %C{1.} [%t] %m%n</Pattern>
        </encoder>
        <!-- 循环覆盖的策略 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 每天归档或当当天日志超过10M时归档 -->
            <fileNamePattern>
                <!-- 归档到哪里 -->
                ${LOGS}/archived/spring-boot-logger-%d{yyyy-MM-dd}.%i.log
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 10M在这里定义的 -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>

    <!-- 对于file以及console都是大于info的就记录 -->
    <root level="info">
        <appender-ref ref="RollingFile" />
        <appender-ref ref="Console" />
    </root>
</configuration>

根据上述xml中的注释，可以进行简单的配置，满足基本需要了，接下来我们看看两个不同类型的log。一个是业务日志，追踪一些用户行为；另一个是性能日志，记录一些耗时操作，或是DB操作的时间。

为了方便的写log，可以借助lombok的@Slf4j注解，在类上添加一个Slf4j注解后，就可以在该类中直接调用log.info或log.error等方法。

@RestController
@RequestMapping("/user")
@Slf4j
public class PassportController {

    @Autowired
    private PassportService passportService;

    @GetMapping("/isUserExisting")
    public JSONResult isUserExisting(@RequestParam(defaultValue = "") String username) {
        if (StringUtils.isBlank(username)) {
            return JSONResult.error("username can not be empty");
        }
        Boolean isExisting = passportService.isUserExisting(username);
        log.info("is existing: {}", isExisting);
        return JSONResult.success(isExisting);
    }
}

这个注解做了什么呢？打开这个注解的定义，我们就会发现，它就是在编译期间给这个类加上了一个私有变量，输出是会带上类名及方法名，方便快捷。

public class LogExample {
  private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(LogExample.class);
}

给Service添加log

最简单直接的方式就是直接在每个service上添加一个注解，然后在想打log的地方，使用log.xxx。功能上当然是没有问题的了，但是会有很多重复代码，有什么方式可以一劳永逸呢？这就要借助Spring的AOP，它有什么作用呢，log在同一的地方定义，并告诉它需要给那些类，方法添加log即可。

1. 添加依赖

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

2. 写一个AOP

@Aspect
@Component
@Slf4j
public class ServiceLogAspect {

    @Around("execution(* com.iossocket.service.impl..*.*(..))")
    public Object recordTime(ProceedingJoinPoint joinPoint) throws Throwable {
        Object target = joinPoint.getTarget();
        Signature sig = joinPoint.getSignature();
        log.info("====== 开始执行 {}.{} ======", target.getClass(), sig.getName());

        long begin = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        long end = System.currentTimeMillis();
        long takeTime = end - begin;

        if (takeTime > 3000) {
            log.error("====== 执行结束，耗时：{} 毫秒 ======", takeTime);
        } else if (takeTime > 2000) {
            log.warn("====== 执行结束，耗时：{} 毫秒 ======", takeTime);
        } else {
            log.info("====== 执行结束，耗时：{} 毫秒 ======", takeTime);
        }

        return result;
    }
}

看代码就可以知道一二了，@Aspect这个注解声明了这个类是一个切面，@Around声明下面这个方法会在execution(* com.iossocket.service.impl..*.*(..))，也就是在所有service方法的前后做拦截，被拦截的方法由Object result = joinPoint.proceed();被执行，没有破坏原有业务逻辑，通过参数ProceedingJoinPoint，可以拿到原方法的类名，函数名，参数列表等等（其余的打开源码进行查阅），也可以像上述代码一样监控一下这个service的耗时。

给SQL添加log

上面的例子，给出了如何通过AOP来添加log，如果想要监控sql的执行呢？

1. 引入p6spy

<dependency>            
  <groupId>p6spy</groupId>
  <artifactId>p6spy</artifactId>
  <version>3.8.6</version>
</dependency>

2. 在application.yml中更改jdbc drivier以及url

spring:
  datasource:
    type: com.zaxxer.hikari.HikariDataSource                  # 数据源类型：HikariCP
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver       # mysql驱动 for p6spy
    url: jdbc:p6spy:mysql://localhost:3306/foodie-shop-dev?useUnicode=true&characterEncoding=UTF-8&useSSL=false
    username: root
    password: 123456

3. 添加p6spy的配置文件spy.properties:

# 指定应用的日志拦截模块,默认为com.p6spy.engine.spy.P6SpyFactory
module.log=com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
# 设置使用p6spy driver来做代理
deregisterdrivers=true
# 真实JDBC driver , 多个以 逗号 分割 默认为空,比如：com.mysql.jdbc.Driver,oracle.jdbc.driver.OracleDriver
driverlist=com.mysql.cj.jdbc.Driver
# 单行日志
# logMessageFormat=com.p6spy.engine.spy.appender.SingleLineFormat
logMessageFormat=com.iossocket.config.P6SpyLogger
# 使用Slf4J记录sql
appender=com.p6spy.engine.spy.appender.Slf4JLogger
# 日期格式
#dateformat=yyyy-MM-dd HH:mm:ss
# 是否开启慢SQL记录
outagedetection=true
# 慢SQL记录标准，单位秒
outagedetectioninterval=2

logMessageFormat可以选用自带的SingleLineFormat，也可以自定义：

package com.iossocket.config;

import com.p6spy.engine.spy.appender.MessageFormattingStrategy;

import java.time.LocalDateTime;

public class P6SpyLogger implements MessageFormattingStrategy {

    public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
        return !"".equals(sql.trim()) ? "[ " + LocalDateTime.now() + " ] --- | took "
                + elapsed + "ms | " + category + " | connection " + connectionId + "\n "
                + sql + ";" : "";
    }
}

这次log的相关内容已经搞定。