如何优雅的记录业务日志

敞开生长之旅！这是我参加「日新方案 12 月更文应战」的第5天，点击检查活动详情

在开发中，除了体系日志外，很多时候咱们还需要记载事务日志。事务日志的记载一般不需要很精细，仅记载要害状况改变的时间点、及前后数据改变即可。当然言语为Java，依据Spring框架。

咱们学习Spring AOP时，了解到其应用场景中，比较重要的一个便是能够用来做日志记载。这种的话，能够依据切入点(Point Cut)类型的不同来到达不同的作用。比方能够阻拦一切的Controller来记载恳求来历IP、恳求参数、呼应成果、耗时等。

1. 记载API访问日志

简略的示例，并非本文要点。经过阻拦一切的Controller控制器，来记载一切的输入、输出。

1.1 Aspect代码示例

@Slf4j
@Aspect
@Order(1)
@Component
public class WebLogAspect {
    private static final Set<String> EXCLUDE_LOG_URIS = Set.of(
    );
    @Pointcut("execution(public * com.example.*.controller.*.*(..))")
    public void logPc() {}
    @Before("logPc()")
    public void doBefore(JoinPoint jp) {
        final HttpServletRequest request = getRequest();
        if (Objects.isNull(request)) {
            return;
        }
        //
        long startTime = System.currentTimeMillis();
        final WebLog.WebLogBuilder wlb = WebLog.builder();
        /* 合作Swagger运用
        final MethodSignature signature = (MethodSignature) jp.getSignature();
        final Method method = signature.getMethod();
        if (method.isAnnotationPresent(ApiOperation.class)) {
            ApiOperation ao = method.getAnnotation(ApiOperation.class);
            wlb.desc(ao.value());
        }
         */
        final String requestURI = request.getRequestURI();
        // 恳求入参
        if (EXCLUDE_LOG_URIS.contains(requestURI)) {
            wlb.parameter("***");
        } else {
            wlb.parameter(jp.getArgs());
        }
        // 其他参数
        wlb.beginTime(startTime);
        wlb.methodName(request.getMethod());
        wlb.uri(requestURI).ip(CommonUtil.getIpAddress(request));
        // 日志输出
        final WebLog webLog = wlb.build();
        log.info("[接口入参] {}", JSONUtil.toJsonStr(webLog));
    }
    @Around("logPc()")
    public Object doAround(ProceedingJoinPoint jp) throws Throwable {
        final HttpServletRequest request = getRequest();
        if (Objects.isNull(request)) {
            return jp.proceed();
        }
        //
        final WebLog.WebLogBuilder wlb = WebLog.builder();
        long startTime = System.currentTimeMillis();
        final Object proceed = jp.proceed();
        long endTime = System.currentTimeMillis();
        /* 合作Swagger运用
        final MethodSignature signature = (MethodSignature) jp.getSignature();
        final Method method = signature.getMethod();
        if (method.isAnnotationPresent(ApiOperation.class)) {
            ApiOperation ao = method.getAnnotation(ApiOperation.class);
            wlb.desc(ao.value());
        }
         */
        final String requestURI = request.getRequestURI();
        // 恳求入参
        if (EXCLUDE_LOG_URIS.contains(requestURI)) {
            wlb.parameter("***").result("***");
        } else {
            wlb.parameter(jp.getArgs()).result(proceed);
        }
        // 其他参数
        wlb.beginTime(startTime).costTime(endTime-startTime);
        wlb.methodName(request.getMethod());
        wlb.uri(requestURI).ip(CommonUtil.getIpAddress(request));
        // 日志输出
        final WebLog webLog = wlb.build();
        log.info("[接口出参] {}", JSONUtil.toJsonStr(webLog));
        //
        return proceed;
    }
    private HttpServletRequest getRequest() {
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        return Optional.ofNullable(attributes).map(ServletRequestAttributes::getRequest).orElse(null);
    }
}

部分日志重复，在@Before和@Around两处记载。在控制器内或许抛出一些RunTimeException这些会由ExceptionHandler大局反常处理器阻拦处理，这里不再细讲。后续单独一篇文章解说。

在实践运用时，发现有些不重要但查询数据量比较大的接口。比方查询某某分页数据，会导致parameter或result俩参数打印出很多字符串。所以加了一层判别，遇到这种接口忽略其参数和返回值。但保存其他数据。

其实这样打印日志，是存在一些问题的：

• 日志的存储是个问题，如果访问量比较大，日志增加飞快。
• 打印日志是比较耗时的，尤其是将lineNo打印。
• 存在必定安全隐患。究竟将一切输入输出均露出在日志中。

1.2 Controller示例及日志

@Slf4j
@RestController
@RequestMapping("leads")
@RequiredArgsConstructor
public class LeadController {
    private final LeadService leadService;
    @PostMapping
    public RestResp<Boolean> addLeads(@Validated @RequestBody LeadReqVO vo) {
        final boolean result = leadService.addLead(vo);
        return RestResp.ok(result);
    }
}

模仿恳求

### 创立头绪
POST http://localhost:28800/leads
Content-Type: application/json
{
  "username": "小明的妈妈",
  "phone": "+5633089972",
  "email": "ming.xiao22@gmail.com",
  "channel": "OA-XX-XX",
  "subject": "Chinese"
}

检查日志

2022-11-30 15:13:36.737  INFO 87959 --- [io-28800-exec-1] c.e.s.c.WebLogAspect  : [接口入参] {"costTime":0,"parameter":[{"phone":"+5633089972","subject":"Chinese","channel":"OA-XX-XX","email":"ming.xiao22@gmail.com","username":"小明的妈妈"}],"ip":"127.0.0.1","methodName":"POST","beginTime":1669792416714,"uri":"/leads"}
2022-11-30 15:13:36.752  INFO 87959 --- [io-28800-exec-1] c.e.s.c.WebLogAspect  : [接口出参] {"result":{"msg":"ok","code":200,"data":false},"costTime":37,"parameter":[{"phone":"+5633089972","subject":"Chinese","channel":"OA-XX-XX","email":"ming.xiao22@gmail.com","username":"小明的妈妈"}],"ip":"127.0.0.1","methodName":"POST","beginTime":1669792416714,"uri":"/leads"}

2 事务日志记载

在留资->商机过程中，因为CRM运用的是外部第三方服务。导致数据大约有两次首要的交互。

• 留资进线: 留资是在自研落地页。用户提交到咱们体系内部，经过简略数据处理后。定时分批次推送到CRM中。
• 头绪转商机: 留资进入到CRM中，会以头绪的形式存在。此时出售能够跟进该头绪，当能够转为商机时。会有转商机动作，该动作需要携带出售完善后的数据，转到咱们体系中。此时会在体系中发送创立账号等操作，便于家长后续预定试听课等流程。

开始这块是只有一些体系日志。当发生一些意外状况时，经常会被事务方要求查询某某家长的留资、进线、转商机等等时间轴。这个场景是很费时费力的事情。一个工单过来或许就要处理几个小时，很或许终究发现这不是咱们的问题。

所以咱们需要这么一套东西，来记载家长留资->进线->转商机->商机后续动作整个流程。(逻辑已简化)

首要模块有:

• 头绪(Lead)
• 商机(Deal)
• 家长(Parent)
• 学生(Student)

触及的动作大约有:

• 头绪_进线(->CRM)
• 头绪_转商机(<-CRM)
• 商机_一切者(出售)被修正(<-CRM)
• 商机_成单同步(->CRM)

描绘完大约事务场景后，咱们开始着手规划。因为这些事务逻辑底子现已存在，咱们只是要在要害节点做一些记载。并不需要特别的细节，这种场景很合适AOP的思维。

2.1 日志记载目标格局

• bizId: 事务ID。如头绪ID、商机ID
• module: 模块。头绪、商机等
• type: 动作。如头绪转商机等
• param: 参数。看详细事务场景

为了便利获取bizId，咱们创立个接口。经过实现该接口中的办法，来露出事务ID。
一起，为了标准。还需新建几个枚举类。

/**
 * 事务ID获取口
 *
 * @author lpe234
 */
public interface BizIdentify {
    /**
     * 获取BizId (大部分状况是 DealId)
     *
     * @return bizId
     */
    String getBizId();
}
@Getter
@ToString
@AllArgsConstructor
public enum EventLogModule {
    LEADS("LEADS", "头绪", "Leads"),
    DEALS("DEALS", "商机", "Deals"),
    PARENTS("PARENTS", "家长", "Accounts"),
    STUDENTS("STUDENTS", "学生", "Contacts"),
    ;
    private final String key;
    private final String val;
    private final String alias;
}
@Getter
@ToString
@AllArgsConstructor
public enum EventLogType {
    CONTACT_TO_LEADS("CONTACT_TO_LEADS", "留资进线"),
    LEAD_TO_DEAL("LEAD_TO_DEAL", "头绪转商机"),
    CHANGE_CC("CHANGE_CC", "修正CC"),
    ORDER_CLOSED_WON("ORDER_CLOSED_WON", "已成单回传"),
    ;
    private final String key;
    private final String val;
}

2.2 定义注解

经过注解的办法。能够很好的去标识，哪些办法需要被记载。而且注解能够合作SpEL来实现一些更灵活的操作。如本注解中的logArg，就可便利的标示参数名并经过反射办法来获取参数详细内容。

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface BizLog {
    /**
     * 日志记载模块
     *
     * @return logModule
     */
    EventLogModule logModule() default EventLogModule.DEALS;
    /**
     * 日志记载原因
     *
     * @return logType
     */
    EventLogType logType();
    /**
     * 需要记载的参数
     * @return param name
     */
    String logArg() default "vo";
}

2.3 事务日志切面

思维很简略，经过@BizLog注解来标识哪些办法需要处理。在进入办法前，经过反射办法将所需内容获取到，并记载到日志体系。本文直接运用log.info来模仿。事务实践场景，存储的ES。首要为了便利检索。

@Slf4j
@Aspect
@Component
public class BizLogAspect {
    @Pointcut("@annotation(com.example.sg.annotation.BizLog)")
    public void logPointCut() {}
    @Before("logPointCut()")
    public void logBefore(JoinPoint point) {
        log.debug("[ZOHO日志记载] 切入点 args=>{}", point.getArgs());
        //
        try {
            final BizLog bizLog = getBizLog(point);
            final String logArg = bizLog.logArg();
            Object rawParam = getRawParam(point, logArg);
            if (Objects.isNull(rawParam)) {
                log.error("[ZOHO日志记载] 参数获取反常, 请检查 methodSign=>{}, logArg=>{}", point.getSignature(), logArg);
                return;
            }
            // 商机ID
            String dealId = null;
            if (rawParam instanceof BizIdentify) {
                dealId = ((BizIdentify) rawParam).getBizId();
            }
            // 日志记载
            doSaveLog(bizLog.logModule(), bizLog.logType(), dealId, rawParam);
        } catch (Exception ex) {
            log.warn("[ZOHO日志记载] 反常 ex=>{}", ex.getLocalizedMessage(), ex);
        }
    }
    private static BizLog getBizLog(JoinPoint point) {
        final MethodSignature methodSign = (MethodSignature) point.getSignature();
        final Method method = methodSign.getMethod();
        return method.getAnnotation(BizLog.class);
    }
    private static Object getRawParam(JoinPoint point, String argName) {
        final Object[] args = point.getArgs();
        final MethodSignature methodSign = (MethodSignature) point.getSignature();
        final int indexOf = ArrayUtils.indexOf(methodSign.getParameterNames(), argName);
        if (indexOf > -1) {
            return args[indexOf];
        }
        return null;
    }
    private void doSaveLog(EventLogModule logModule, EventLogType logType, String bizId, Object rawParam) {
        log.info("\n" +
                "[事务日志] ----------------\n" +
                "module: {}\n" +
                "type: {}\n" +
                "bizId: {}\n" +
                "param: {}\n" +
                "---------------------------\n", logModule, logType, bizId, rawParam);
    }
}

2.4 来模仿其间一个场景

模仿头绪转商机场景。由CRM内部工作流触发，发起HTTP恳求。

@Data
public class LeadToDealReqVO implements BizIdentify {
    private String dealId;
    private String phone;
    private String email;
    private String channel;
    // 商机阶段
    private String stage;
    /**
     * 获取BizId (大部分状况是 DealId)
     *
     * @return bizId
     */
    @Override
    public String getBizId() {
        return dealId;
    }
}

事务处理

@Slf4j
@Service
public class LeadToDealServiceImpl implements LeadToDealService {
    @BizLog(logType = EventLogType.LEAD_TO_DEAL)
    @Override
    public boolean leadToDeal(LeadToDealReqVO vo) {
        log.info("[头绪转商机] 处理中...");
        return true;
    }
}

触发执行，检查日志

2022-11-30 17:33:30.839  INFO 22986 --- [io-28800-exec-1] c.e.s.c.WebLogAspect  : [接口入参] {"costTime":0,"parameter":[{"stage":"To Schedule","phone":"+5633089972","dealId":"1234567890","channel":"OA-XX-XX","email":"ming.xiao22@gmail.com"}],"ip":"127.0.0.1","methodName":"POST","beginTime":1669800810820,"uri":"/leadToDeal"}
2022-11-30 17:33:30.856  INFO 22986 --- [io-28800-exec-1] c.e.s.c.BizLogAspect  : 
[事务日志] ----------------
module: EventLogModule.DEALS(key=DEALS, val=商机, alias=Deals)
type: EventLogType.LEAD_TO_DEAL(key=LEAD_TO_DEAL, val=头绪转商机)
bizId: 1234567890
param: LeadToDealReqVO(dealId=1234567890, phone=+5633089972, email=ming.xiao22@gmail.com, channel=OA-XX-XX, stage=To Schedule)
---------------------------
2022-11-30 17:33:30.881  INFO 22986 --- [io-28800-exec-1] c.e.s.service.LeadToDealServiceImpl      : [头绪转商机] 处理中...
2022-11-30 17:33:30.882  INFO 22986 --- [io-28800-exec-1] c.e.s.c.WebLogAspect  : [接口出参] {"result":{"msg":"ok","code":200,"data":true},"costTime":62,"parameter":[{"stage":"To Schedule","phone":"+5633089972","dealId":"1234567890","channel":"OA-XX-XX","email":"ming.xiao22@gmail.com"}],"ip":"127.0.0.1","methodName":"POST","beginTime":1669800810820,"uri":"/leadToDeal"}

3 跋文

其实在事务代码实践修正过程中，发现部分状况是没办法运用注解解决的。究其原因是代码写的不标准，并不具有高内聚低耦合的特性。

其间一个事务留资进线，需要在本地做很多的校验和处理，前几篇规划模式底子都跟这块的数据处理有联系。在行将推送到CRM的函数中，又对数据做了一些处理。在函数外部，底子拿不到终究的参数。

其实这种处理办法也简略：

• 拆分函数，将处理和实践推送拆开，使其契合单一职责。
• 做必定程度的忍受，保存日志服务对外提供功能，做必定程度的兼容?。

另: tech.meituan.com/…