如何优雅的记录业务日志
站长
· 阅读数 20
在开发中，除了系统日志外，很多时候我们还需要记录业务日志。业务日志的记录通常不需要很精细，仅记录关键状态改变的时间点、及前后数据变化即可。当然语言为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的函数中，又对数据做了一些处理。在函数外部，根本拿不到最终的参数。
其实这种处理方式也简单：
- 拆分函数，将处理和实际推送拆开，使其符合
单一职责。 - 做一定程度的容忍，保存日志服务对外提供功能，做一定程度的
兼容?。