日志系统搭建

案例链接

京东云技术团队 https://www.cnblogs.com/jingdongkeji/p/17816753.html

美团技术团队 https://tech.meituan.com/2021/09/16/operational-logbook.html

美团高性能终端日志系统建设时间 https://tech.meituan.com/2022/11/03/logan-real-time-log.html

基于AOP方式实现

1
https://github.com/macrozheng/mall/blob/master/mall-common/src/main/java/com/macro/mall/common/log/WebLogAspect.java
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
126
127
128
129
130
mall-common/src/main/java/com/macro/mall/common/log/WebLogAspect.java


package com.macro.mall.common.log;

import cn.hutool.core.util.StrUtil;
import cn.hutool.core.util.URLUtil;
import cn.hutool.json.JSONUtil;
import com.macro.mall.common.domain.WebLog;
import com.macro.mall.common.util.RequestUtil;
import io.swagger.annotations.ApiOperation;
import net.logstash.logback.marker.Markers;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.*;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.lang.reflect.Method;
import java.lang.reflect.Parameter;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
import java.util.Map;

/**
* 统一日志处理切面
* Created by macro on 2018/4/26.
*/
@Aspect
@Component
@Order(1)
public class WebLogAspect {
private static final Logger LOGGER = LoggerFactory.getLogger(WebLogAspect.class);

@Pointcut("execution(public * com.macro.mall.controller.*.*(..))||execution(public * com.macro.mall.*.controller.*.*(..))")
public void webLog() {
}

@Before("webLog()")
public void doBefore(JoinPoint joinPoint) throws Throwable {
}

@AfterReturning(value = "webLog()", returning = "ret")
public void doAfterReturning(Object ret) throws Throwable {
}

@Around("webLog()")
public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {
long startTime = System.currentTimeMillis();
//获取当前请求对象
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
//记录请求信息(通过Logstash传入Elasticsearch)
WebLog webLog = new WebLog();
Object result = joinPoint.proceed();
Signature signature = joinPoint.getSignature();
MethodSignature methodSignature = (MethodSignature) signature;
Method method = methodSignature.getMethod();
if (method.isAnnotationPresent(ApiOperation.class)) {
ApiOperation log = method.getAnnotation(ApiOperation.class);
webLog.setDescription(log.value());
}
long endTime = System.currentTimeMillis();
String urlStr = request.getRequestURL().toString();
webLog.setBasePath(StrUtil.removeSuffix(urlStr, URLUtil.url(urlStr).getPath()));
webLog.setUsername(request.getRemoteUser());
webLog.setIp(RequestUtil.getRequestIp(request));
webLog.setMethod(request.getMethod());
webLog.setParameter(getParameter(method, joinPoint.getArgs()));
webLog.setResult(result);
webLog.setSpendTime((int) (endTime - startTime));
webLog.setStartTime(startTime);
webLog.setUri(request.getRequestURI());
webLog.setUrl(request.getRequestURL().toString());
Map<String,Object> logMap = new HashMap<>();
logMap.put("url",webLog.getUrl());
logMap.put("method",webLog.getMethod());
logMap.put("parameter",webLog.getParameter());
logMap.put("spendTime",webLog.getSpendTime());
logMap.put("description",webLog.getDescription());
// LOGGER.info("{}", JSONUtil.parse(webLog));
LOGGER.info(Markers.appendEntries(logMap), JSONUtil.parse(webLog).toString());
return result;
}

/**
* 根据方法和传入的参数获取请求参数
*/
private Object getParameter(Method method, Object[] args) {
List<Object> argList = new ArrayList<>();
Parameter[] parameters = method.getParameters();
for (int i = 0; i < parameters.length; i++) {
//将RequestBody注解修饰的参数作为请求参数
RequestBody requestBody = parameters[i].getAnnotation(RequestBody.class);
if (requestBody != null) {
argList.add(args[i]);
}
//将RequestParam注解修饰的参数作为请求参数
RequestParam requestParam = parameters[i].getAnnotation(RequestParam.class);
if (requestParam != null) {
Map<String, Object> map = new HashMap<>();
String key = parameters[i].getName();
if (!StrUtil.isEmpty(requestParam.value())) {
key = requestParam.value();
}
if(args[i]!=null){
map.put(key, args[i]);
argList.add(map);
}
}
}
if (argList.size() == 0) {
return null;
} else if (argList.size() == 1) {
return argList.get(0);
} else {
return argList;
}
}
}

京东AOP

一种简化操作日志记录方案

一、背景:

后台系统配置越来越多的出现需要进行日志记录的功能,且当前已有日志记录不可复用,需要统一日志记录格式,提高日志记录开发效率。

二、预期效果展示:

新建动作:

img

修改动作:

img

删除动作:

img

三、数据存储:

注:可以选择其他存储方式,这里只简单举个例子

1
2
3
4
5
6
7
`biz_id` bigint(20) NOT NULL DEFAULT 0 COMMENT '业务id',
`biz_type` tinyint(4) NOT NULL DEFAULT 0 COMMENT '业务类型',
`operator_id` varchar(128) NOT NULL DEFAULT '' COMMENT '操作人',
`operate_content` text COMMENT '操作内容',
`change_before` text COMMENT '修改前',
`change_after` text COMMENT '修改后',
`create_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间'

四、原理简述:

日志构建关注两个对象,一个是修改前,修改后:

修改前:null + 修改后:X = 新建

修改前:Y + 修改后:X = 更新

修改前:Y + 修改后:null = 删除

修改内容判断依据传入的两个对象,对两个对象的每个属性进行逐一对比,如果发生变化则是需要进行日志记录字段;关注的属性使用注解进行标注。

五、具体实现:

注解

1
2
3
4
5
6
7
8
9
10
11
12
@Target(ElementType.FIELD)
@Retention(RetentionPolicy.RUNTIME)
@Inherited
@Documented
public @interface LogField {

String name() default "";

String valueFun() default "";

boolean spliceValue() default true;
}

name: name值表示该字段如果被修改,应在日志中记录的字段名;默认取字段名

valueFun: 表示获取改变字段内容的获取方法;默认取字段值,若valueFun方法不存在,则取默认值

spliceValue: 日志是否需要拼接变更内容,默认拼接

注解处理:

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
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220

/**
* @author a80406
* @since 2024/3/11 10:03
*/
@Service
@Slf4j
public class OperateLogService {
@Resource
private CommonOperateLogService commonOperateLogService;

enum ActionEnum{
ADD("新建"),
UPDATE("修改"),
DELETE("删除");

ActionEnum(String desc) {
this.desc = desc;
}
public String desc;
}

private int insertLog(CommonOperatorLog commonOperatorLog){
String result = commonOperateLogService.insertLog(JSON.toJSONString(commonOperatorLog));
Response response = JSON.parseObject(result, Response.class);
return Objects.isNull(response) || ApiResponse.Status.fail.equals(response.getStatus()) ? 0 : (int) response.getContent();
}

public PageOutput<CommonOperatorLog> queryList(Long bizId, Integer bizType, Integer pageNum, Integer pageSize){
String result = commonOperateLogService.queryLog(bizId, bizType, pageNum, pageSize);
PageOutput pageOutput = JSON.parseObject(result, new TypeReference<PageOutput<CommonOperatorLog>>() {});
return pageOutput;
}

/**
*
* @param operatorId 操作人
* @param bizId 操作Id
* @param bizType 操作类型
* @param target 修改后的数据的对象
* @param original 修改前的对象
* @param <T> 传入数据的类型
*/
public <T> void saveLog(String operatorId,Long bizId, Integer bizType, T target, T original){
if(StrUtil.isBlank(operatorId) || (Objects.isNull(target) && Objects.isNull(original))){
throw new IllegalArgumentException();
}
if(Objects.nonNull(target) && Objects.nonNull(original) && !target.getClass().isAssignableFrom(original.getClass())){
throw new IllegalArgumentException();
}
ActionEnum action = getAction(target, original);
List<Triple<String, String, LogField>> changeInfos = getChangeInfoList(target, original);
List<String> changeInfoList = new ArrayList<>();
if(CollectionUtil.isEmpty(changeInfos) && !ActionEnum.UPDATE.equals(action)){
changeInfoList.add(0, action.desc);
}else if (CollectionUtil.isEmpty(changeInfos)){
return;
}else {
changeInfoList = changeInfos.stream().map(i -> i.getRight().spliceValue() ?
action.desc + StrUtil.join("为:", i.getLeft(), i.getMiddle()) :
action.desc + StrUtil.join("了", i.getLeft()))
.collect(Collectors.toList());
}

String operateContext = StrUtil.join(changeInfoList, "\n");
operateContext = operateContext.replaceAll("\"","")
.replaceAll("\\[","").replaceAll("\\]","");
CommonOperatorLog operatorLog = new CommonOperatorLog();
operatorLog.setBizId(bizId);
operatorLog.setBizType(bizType);
operatorLog.setOperateContent(operateContext);
operatorLog.setOperatorId(operatorId);
operatorLog.setChangeBefore(JSON.toJSONString(original));
operatorLog.setChangeAfter(JSON.toJSONString(target));
this.insertLog(operatorLog);
}

private ActionEnum getAction(Object target, Object original){
ActionEnum action = ActionEnum.ADD;
if(Objects.nonNull(target) && Objects.nonNull(original)){
action = ActionEnum.UPDATE;
}else if(Objects.nonNull(target)){
action = ActionEnum.ADD;
}else if (Objects.nonNull(original)){
action = ActionEnum.DELETE;
}
return action;
}

/**
* 获取修改信息的list
* @param target
* @param original
* @param <T>
* @return
*/
private<T> List<Triple<String, String, LogField>> getChangeInfoList(T target, T original){
if(Objects.isNull(target) || Objects.isNull(original)){
return new ArrayList<>();
}
List<Pair<Field, Object>> targetFields = allFields(target);
List<Pair<Field, Object>> originalFields = allFields(original);
if(targetFields.size() != originalFields.size()){
//理论上不可能执行到这
throw new IllegalArgumentException();
}

List<Triple<String, String, LogField>> result = new ArrayList<>();
for (int i = 0; i < targetFields.size(); i++) {
Pair<Field, Object> targetField = targetFields.get(i);
Pair<Field, Object> originalField = originalFields.get(i);
ReflectionUtils.makeAccessible(targetField.getKey());
ReflectionUtils.makeAccessible(originalField.getKey());
Object targetValue = ReflectionUtils.getField(targetField.getKey(), targetField.getValue());
Object originalValue = ReflectionUtils.getField(originalField.getKey(), originalField.getValue());
if(targetValue != originalValue && (Objects.isNull(targetValue) ||
(!targetValue.equals(originalValue) &&
compareTo(Pair.of(targetField.getKey(), targetValue), Pair.of(originalField.getKey(), originalValue)) &&
!JSON.toJSONString(targetValue).equals(JSON.toJSONString(originalValue))))){
result.add(Triple.of(getFieldName(targetField.getKey()), getFieldValue(targetField.getKey(), targetField.getValue()), targetField.getKey().getAnnotation(LogField.class)));
}
}
return result;
}

private boolean compareTo(Pair<Field, Object> targetField, Pair<Field, Object> originalField){
Field field = targetField.getKey();
Object targetValue = targetField.getValue();
Object originalValue = originalField.getValue();
boolean canCompare = Arrays.stream(field.getType().getInterfaces()).anyMatch(i -> Comparable.class.getName().equals(i.getName()));
if(canCompare && Objects.nonNull(targetValue) && Objects.nonNull(originalValue)){
Method compareTo = ReflectionUtils.findMethod(field.getType(), "compareTo", field.getType());
if(Objects.isNull(compareTo)){
return true;
}
Object compared = ReflectionUtils.invokeMethod(compareTo, targetValue, originalValue);
return (int)compared != 0 ;
}
return true;
}

private <T> List<Pair<Field, Object>> allFields(T obj){
List<Triple<Field, Object, Boolean>> targetField = findField(obj);
List<Triple<Field, Object, Boolean>> allField = Lists.newArrayList(targetField);
List<Triple<Field, Object, Boolean>> needRemove = new ArrayList<>();
for (int i = 0; i < allField.size(); i++) {
Triple<Field, Object, Boolean> fieldObjectDes = allField.get(i);
if(!fieldObjectDes.getRight()){
ReflectionUtils.makeAccessible(fieldObjectDes.getLeft());
Object fieldV = ReflectionUtils.getField(fieldObjectDes.getLeft(), fieldObjectDes.getMiddle());
List<Triple<Field, Object, Boolean>> fieldList = findField(fieldV);
if(CollectionUtil.isNotEmpty(fieldList)){
allField.addAll(fieldList);
needRemove.add(fieldObjectDes);
}
}
}

if(CollectionUtil.isNotEmpty(needRemove)){
allField.removeAll(needRemove);
}
return allField.stream().map(i->Pair.of(i.getLeft(), i.getMiddle())).collect(Collectors.toList());
}

private <T> List<Triple<Field, Object, Boolean>> findField(T obj){
Class<?> objClass = obj.getClass();
Field[] declaredFields = objClass.getDeclaredFields();
List<Field> allFields = Lists.newArrayList(declaredFields);
if(Objects.nonNull(objClass.getSuperclass())){
Field[] superClassFields = objClass.getSuperclass().getDeclaredFields();
allFields.addAll(Arrays.asList(superClassFields));
}
List<Triple<Field, Object, Boolean>> result = new ArrayList<>();
for (Field declaredField : allFields) {
LogField annotation = declaredField.getAnnotation(LogField.class);
if(Objects.nonNull(annotation)){
result.add(Triple.of(declaredField, obj, declaredField.getType().getPackage().getName().startsWith("java")));
}
}
return result;
}


private String getFieldName(Field field){
LogField annotation = field.getAnnotation(LogField.class);
String name = annotation.name();
if(StrUtil.isBlank(name)){
name = field.getName();
}
return name;
}

private <T> String getFieldValue(Field field, T targetObj){
LogField annotation = field.getAnnotation(LogField.class);
if(!annotation.spliceValue()){
return "";
}
String valueFun = annotation.valueFun();
if(StrUtil.isBlank(valueFun)){
Object fieldValue = ReflectionUtils.getField(field, targetObj);
return getStrValue(fieldValue);
}else {
Method valueMethod = ReflectionUtils.findMethod(targetObj.getClass(), valueFun);
if(Objects.isNull(valueMethod)){
Object fieldValue = ReflectionUtils.getField(field, targetObj);
return getStrValue(fieldValue);
}else {
ReflectionUtils.makeAccessible(valueMethod);
Object invokeMethodRes = ReflectionUtils.invokeMethod(valueMethod, targetObj);
return getStrValue(invokeMethodRes);
}
}
}

private String getStrValue(Object fieldValue){
List<String> emptyStr = ImmutableList.of("\"\"", "{}","[]");
String value = Objects.isNull(fieldValue) ? "无" : JSON.toJSONString(fieldValue);
return emptyStr.contains(value) ? "无" : value;
}
}

六、使用示例:

1、使用的日志记录对象(这个对象只为日志服务)

1
2
3
4
5
6
7
8
9
10
public class SubsidyRateLog {

@LogField(name = "补贴率名称")
private String name;

@LogField(name = "适用城市", valueFun = "getCityNames")
private List<Integer> cityIds;

private List<String> cityNames;
}

name是直接展示字段,所以修改值即name本身的值;cityIds 是我们关心比较字段,当它值不一样时进行 字段value 值获取,这个值是展示在前端的,所以可以根据需要进行格式定义,默认是将取到的值进行toJSON;当前例子中获取的是getCityNames方法返回的值;

2、无专用日志对象(大多数时候我们有自己的实体对象,但不包含具体日志描述字段),需要进行继承

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public class SubsidyRate {

@LogField(name = "补贴率名称")
private String name;

@LogField(name = "适用城市", valueFun = "getCityNames")
private List<Integer> cityIds;
}

@Data
public class SubsidyRateLog extends SubsidyRate{

private List<String> cityNames;
}

此方式适用于兼容现有对象,而不去破坏现有对象的完整性

3、对象包含子对象(比较复杂的大对象,如Task中的券信息)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public class SubsidyRateLog {

@LogField(name = "补贴率名称")
private String name;

@LogField
private Address address;
}

public class Address {
@LogField(name = "省份")
private String province;
@LogField(name = "城市")
private String city;
}

此情况下会将所有信息平铺,如果 Address 中 没有_LogField_ 注解,那么会直接使用将获取address值,如果存在注解,那么将忽略address本身,只关注注解字段。


美团技术团队

如何优雅地记录操作日志?

操作日志几乎存在于每个系统中,而这些系统都有记录操作日志的一套 API。操作日志和系统日志不一样,操作日志必须要做到简单易懂。所以如何让操作日志不和业务逻辑耦合,如何让操作日志的内容易于理解,让操作日志的接入更加简单?上面这些都是本文要回答的问题,主要围绕着如何“优雅”地记录操作日志展开描述。

  1. 操作日志的使用场景

例子

例子

系统日志和操作日志的区别

系统日志:系统日志主要是为开发排查问题提供依据,一般打印在日志文件中;系统日志的可读性要求没那么高,日志中会包含代码的信息,比如在某个类的某一行打印了一个日志。

操作日志:主要是对某个对象进行新增操作或者修改操作后记录下这个新增或者修改,操作日志要求可读性比较强,因为它主要是给用户看的,比如订单的物流信息,用户需要知道在什么时间发生了什么事情。再比如,客服对工单的处理记录信息。

操作日志的记录格式大概分为下面几种: * 单纯的文字记录,比如:2021-09-16 10:00 订单创建。 * 简单的动态的文本记录,比如:2021-09-16 10:00 订单创建,订单号:NO.11089999,其中涉及变量订单号“NO.11089999”。 * 修改类型的文本,包含修改前和修改后的值,比如:2021-09-16 10:00 用户小明修改了订单的配送地址:从“金灿灿小区”修改到“银盏盏小区” ,其中涉及变量配送的原地址“金灿灿小区”和新地址“银盏盏小区”。 * 修改表单,一次会修改多个字段。

  1. 实现方式

2.1 使用 Canal 监听数据库记录操作日志

Canal 是一款基于 MySQL 数据库增量日志解析,提供增量数据订阅和消费的开源组件,通过采用监听数据库 Binlog 的方式,这样可以从底层知道是哪些数据做了修改,然后根据更改的数据记录操作日志。

这种方式的优点是和业务逻辑完全分离。缺点也很明显,局限性太高,只能针对数据库的更改做操作日志记录,如果修改涉及到其他团队的 RPC 的调用,就没办法监听数据库了,举个例子:给用户发送通知,通知服务一般都是公司内部的公共组件,这时候只能在调用 RPC 的时候手工记录发送通知的操作日志了。

2.2 通过日志文件的方式记录

1
2
3
log.info("订单创建")
log.info("订单已经创建,订单编号:{}", orderNo)
log.info("修改了订单的配送地址:从“{}”修改到“{}”, "金灿灿小区", "银盏盏小区")

这种方式的操作记录需要解决三个问题。

问题一:操作人如何记录

借助 SLF4J 中的 MDC 工具类,把操作人放在日志中,然后在日志中统一打印出来。首先在用户的拦截器中把用户的标识 Put 到 MDC 中。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
@Component
public class UserInterceptor extends HandlerInterceptorAdapter {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
//获取到用户标识
String userNo = getUserNo(request);
//把用户 ID 放到 MDC 上下文中
MDC.put("userId", userNo);
return super.preHandle(request, response, handler);
}

private String getUserNo(HttpServletRequest request) {
// 通过 SSO 或者Cookie 或者 Auth信息获取到 当前登陆的用户信息
return null;
}
}

其次,把 userId 格式化到日志中,使用 %X{userId} 可以取到 MDC 中用户标识。

1
<pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern>

问题二:操作日志如何和系统日志区分开

通过配置 Log 的配置文件,把有关操作日志的 Log 单独放到一日志文件中。

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
//不同业务日志记录到不同的文件
<appender name="businessLogAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>logs/business.log</File>
<append>true</append>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>logs/业务A.%d.%i.log</fileNamePattern>
<maxHistory>90</maxHistory>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>10MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
</rollingPolicy>
<encoder>
<pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>

<logger name="businessLog" additivity="false" level="INFO">
<appender-ref ref="businessLogAppender"/>
</logger>

然后在 Java 代码中单独的记录业务日志。

1
2
3
4
5
//记录特定日志的声明
private final Logger businessLog = LoggerFactory.getLogger("businessLog");

//日志存储
businessLog.info("修改了配送地址");

问题三:如何生成可读懂的日志文案

可以采用 LogUtil 的方式,也可以采用切面的方式生成日志模板,后续内容将会进行介绍。这样就可以把日志单独保存在一个文件中,然后通过日志收集可以把日志保存在 Elasticsearch 或者数据库中,接下来看下如何生成可读的操作日志。

2.3 通过 LogUtil 的方式记录日志

1
2
3
4
LogUtil.log(orderNo, "订单创建", "小明")模板
LogUtil.log(orderNo, "订单创建,订单号"+"NO.11089999", "小明")
String template = "用户%s修改了订单的配送地址:从“%s”修改到“%s”"
LogUtil.log(orderNo, String.format(tempalte, "小明", "金灿灿小区", "银盏盏小区"), "小明")

这里解释下为什么记录操作日志的时候都绑定了一个 OrderNo,因为操作日志记录的是:某一个“时间”“谁”对“什么”做了什么“事情”。当查询业务的操作日志的时候,会查询针对这个订单的的所有操作,所以代码中加上了 OrderNo,记录操作日志的时候需要记录下操作人,所以传了操作人“小明”进来。

上面看起来问题并不大,在修改地址的业务逻辑方法中使用一行代码记录了操作日志,接下来再看一个更复杂的例子:

1
2
3
4
5
6
7
8
9
10
11
12
13
private OnesIssueDO updateAddress(updateDeliveryRequest request) {
DeliveryOrder deliveryOrder = deliveryQueryService.queryOldAddress(request.getDeliveryOrderNo());
// 更新派送信息,电话,收件人,地址
doUpdate(request);
String logContent = getLogContent(request, deliveryOrder);
LogUtils.logRecord(request.getOrderNo(), logContent, request.getOperator);
return onesIssueDO;
}

private String getLogContent(updateDeliveryRequest request, DeliveryOrder deliveryOrder) {
String template = "用户%s修改了订单的配送地址:从“%s”修改到“%s”";
return String.format(tempalte, request.getUserName(), deliveryOrder.getAddress(), request.getAddress);
}

可以看到上面的例子使用了两个方法代码,外加一个 getLogContent 的函数实现了操作日志的记录。当业务变得复杂后,记录操作日志放在业务代码中会导致业务的逻辑比较繁杂,最后导致 LogUtils.logRecord() 方法的调用存在于很多业务的代码中,而且类似 getLogContent() 这样的方法也散落在各个业务类中,对于代码的可读性和可维护性来说是一个灾难。下面介绍下如何避免这个灾难。

2.4 方法注解实现操作日志

为了解决上面问题,一般采用 AOP 的方式记录日志,让操作日志和业务逻辑解耦,接下来看一个简单的 AOP 日志的例子。

1
2
3
4
5
@LogRecord(content="修改了配送地址")
public void modifyAddress(updateDeliveryRequest request){
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

我们可以在注解的操作日志上记录固定文案,这样业务逻辑和业务代码可以做到解耦,让我们的业务代码变得纯净起来。可能有同学注意到,上面的方式虽然解耦了操作日志的代码,但是记录的文案并不符合我们的预期,文案是静态的,没有包含动态的文案,因为我们需要记录的操作日志是: 用户%s修改了订单的配送地址,从“%s”修改到“%s”。接下来,我们介绍一下如何优雅地使用 AOP 生成动态的操作日志。

  1. 优雅地支持 AOP 生成动态的操作日志

3.1 动态模板

一提到动态模板,就会涉及到让变量通过占位符的方式解析模板,从而达到通过注解记录操作日志的目的。模板解析的方式有很多种,这里使用了 SpEL(Spring Expression Language,Spring表达式语言)来实现。我们可以先写下期望的记录日志的方式,然后再看下能否实现这样的功能。

1
2
3
4
5
@LogRecord(content = "修改了订单的配送地址:从“#oldAddress”, 修改到“#request.address”")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

通过 SpEL 表达式引用方法上的参数,可以让变量填充到模板中达到动态的操作日志文本内容。 但是现在还有几个问题需要解决: * 操作日志需要知道是哪个操作人修改的订单配送地址。 * 修改订单配送地址的操作日志需要绑定在配送的订单上,从而可以根据配送订单号查询出对这个配送订单的所有操作。 * 为了在注解上记录之前的配送地址是什么,在方法签名上添加了一个和业务无关的 oldAddress 的变量,这样就不优雅了。

为了解决前两个问题,我们需要把期望的操作日志使用形式改成下面的方式:

1
2
3
4
5
6
7
@LogRecord(
content = "修改了订单的配送地址:从“#oldAddress”, 修改到“#request.address”",
operator = "#request.userName", bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

修改后的代码在注解上添加两个参数,一个是操作人,一个是操作日志需要绑定的对象。但是,在普通的 Web 应用中用户信息都是保存在一个线程上下文的静态方法中,所以 operator 一般是这样的写法(假定获取当前登陆用户的方式是 UserContext.getCurrentUser())。

1
operator = "#{T(com.meituan.user.UserContext).getCurrentUser()}"

这样的话,每个 @LogRecord 的注解上的操作人都是这么长一串。为了避免过多的重复代码,我们可以把注解上的 operator 参数设置为非必填,这样用户可以填写操作人。但是,如果用户不填写我们就取 UserContext 的 user(下文会介绍如何取 user )。最后,最简单的日志变成了下面的形式:

1
2
3
4
5
6
@LogRecord(content = "修改了订单的配送地址:从“#oldAddress”, 修改到“#request.address”", 
bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

接下来,我们需要解决第三个问题:为了记录业务操作记录添加了一个 oldAddress 变量,不管怎么样这都不是一个好的实现方式,所以接下来,我们需要把 oldAddress 变量从修改地址的方法签名上去掉。但是操作日志确实需要 oldAddress 变量,怎么办呢?

要么和产品经理 PK 一下,让产品经理把文案从“修改了订单的配送地址:从 xx 修改到 yy” 改为 “修改了订单的配送地址为:yy”。但是从用户体验上来看,第一种文案更人性化一些,显然我们不会 PK 成功的。那么我们就必须要把这个 oldAddress 查询出来然后供操作日志使用了。还有一种解决办法是:把这个参数放到操作日志的线程上下文中,供注解上的模板使用。我们按照这个思路再改下操作日志的实现代码。

1
2
3
4
5
6
7
8
@LogRecord(content = "修改了订单的配送地址:从“#oldAddress”, 修改到“#request.address”",
bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
// 查询出原来的地址是什么
LogRecordContext.putVariable("oldAddress", DeliveryService.queryOldAddress(request.getDeliveryOrderNo()));
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

这时候可以看到,LogRecordContext 解决了操作日志模板上使用方法参数以外变量的问题,同时避免了为了记录操作日志修改方法签名的设计。虽然已经比之前的代码好了些,但是依然需要在业务代码里面加了一行业务逻辑无关的代码,如果有“强迫症”的同学还可以继续往下看,接下来我们会讲解自定义函数的解决方案。下面再看另一个例子:

1
2
3
4
5
6
7
8
@LogRecord(content = "修改了订单的配送员:从“#oldDeliveryUserId”, 修改到“#request.userId”",
bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
// 查询出原来的地址是什么
LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

这个操作日志的模板最后记录的内容是这样的格式:修改了订单的配送员:从 “10090”,修改到 “10099”,显然用户看到这样的操作日志是不明白的。用户对于用户 ID 是 10090 还是 10099 并不了解,用户期望看到的是:修改了订单的配送员:从“张三(18910008888)”,修改到“小明(13910006666)”。用户关心的是配送员的姓名和电话。但是我们方法中传递的参数只有配送员的 ID,没有配送员的姓名可电话。我们可以通过上面的方法,把用户的姓名和电话查询出来,然后通过 LogRecordContext 实现。

但是,“强迫症”是不期望操作日志的代码嵌入在业务逻辑中的。接下来,我们考虑另一种实现方式:自定义函数。如果我们可以通过自定义函数把用户 ID 转换为用户姓名和电话,那么就能解决这一问题,按照这个思路,我们把模板修改为下面的形式:

1
2
3
4
5
6
7
8
@LogRecord(content = "修改了订单的配送员:从“{deliveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.userId}}”",
bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
// 查询出原来的地址是什么
LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

其中 deliveryUser 是自定义函数,使用大括号把 Spring 的 SpEL 表达式包裹起来,这样做的好处:一是把 SpEL(Spring Expression Language,Spring表达式语言)和自定义函数区分开便于解析;二是如果模板中不需要 SpEL 表达式解析可以容易的识别出来,减少 SpEL 的解析提高性能。这时候我们发现上面代码还可以优化成下面的形式:

1
2
3
4
5
6
@LogRecord(content = "修改了订单的配送员:从“{queryOldUser{#request.deliveryOrderNo()}}”, 修改到“{deveryUser{#request.userId}}”",
bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

这样就不需要在 modifyAddress 方法中通过 LogRecordContext.putVariable() 设置老的快递员了,通过直接新加一个自定义函数 queryOldUser() 参数把派送订单传递进去,就能查到之前的配送人了,只需要让方法的解析在 modifyAddress() 方法执行之前运行。这样的话,我们让业务代码又变得纯净了起来,同时也让“强迫症”不再感到难受了。

  1. 代码实现解析

4.1 代码结构

img

上面的操作日志主要是通过一个 AOP 拦截器实现的,整体主要分为 AOP 模块、日志解析模块、日志保存模块、Starter 模块;组件提供了4个扩展点,分别是:自定义函数、默认处理人、业务保存和查询;业务可以根据自己的业务特性定制符合自己业务的逻辑。

4.2 模块介绍

有了上面的分析,已经得出一种我们期望的操作日志记录的方式,那么接下来看看如何实现上面的逻辑。实现主要分为下面几个步骤: * AOP 拦截逻辑 * 解析逻辑 * 模板解析 * LogContext 逻辑 * 默认的 operator 逻辑 * 自定义函数逻辑 * 默认的日志持久化逻辑 * Starter 封装逻辑

4.2.1 AOP 拦截逻辑

这块逻辑主要是一个拦截器,针对 @LogRecord 注解分析出需要记录的操作日志,然后把操作日志持久化,这里把注解命名为 @LogRecordAnnotation。接下来,我们看下注解的定义:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Inherited
@Documented
public @interface LogRecordAnnotation {
String success();

String fail() default "";

String operator() default "";

String bizNo();

String category() default "";

String detail() default "";

String condition() default "";
}

注解中除了上面提到参数外,还增加了 fail、category、detail、condition 等参数,这几个参数是为了满足特定的场景,后面还会给出具体的例子。

参数名 描述 是否必填
success 操作日志的文本模板
fail 操作日志失败的文本版本
operator 操作日志的执行人
bizNo 操作日志绑定的业务对象标识
category 操作日志的种类
detail 扩展参数,记录操作日志的修改详情
condition 记录日志的条件

为了保持简单,组件的必填参数就两个。业务中的 AOP 逻辑大部分是使用 @Aspect 注解实现的,但是基于注解的 AOP 在 Spring boot 1.5 中兼容性是有问题的,组件为了兼容 Spring boot1.5 的版本我们手工实现 Spring 的 AOP 逻辑。

img

切面选择 AbstractBeanFactoryPointcutAdvisor 实现,切点是通过 StaticMethodMatcherPointcut 匹配包含 LogRecordAnnotation 注解的方法。通过实现 MethodInterceptor 接口实现操作日志的增强逻辑。

下面是拦截器的切点逻辑:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public class LogRecordPointcut extends StaticMethodMatcherPointcut implements Serializable {
// LogRecord的解析类
private LogRecordOperationSource logRecordOperationSource;

@Override
public boolean matches(@NonNull Method method, @NonNull Class<?> targetClass) {
// 解析 这个 method 上有没有 @LogRecordAnnotation 注解,有的话会解析出来注解上的各个参数
return !CollectionUtils.isEmpty(logRecordOperationSource.computeLogRecordOperations(method, targetClass));
}

void setLogRecordOperationSource(LogRecordOperationSource logRecordOperationSource) {
this.logRecordOperationSource = logRecordOperationSource;
}
}

切面的增强逻辑主要代码如下:

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
@Override
public Object invoke(MethodInvocation invocation) throws Throwable {
Method method = invocation.getMethod();
// 记录日志
return execute(invocation, invocation.getThis(), method, invocation.getArguments());
}

private Object execute(MethodInvocation invoker, Object target, Method method, Object[] args) throws Throwable {
Class<?> targetClass = getTargetClass(target);
Object ret = null;
MethodExecuteResult methodExecuteResult = new MethodExecuteResult(true, null, "");
LogRecordContext.putEmptySpan();
Collection<LogRecordOps> operations = new ArrayList<>();
Map<String, String> functionNameAndReturnMap = new HashMap<>();
try {
operations = logRecordOperationSource.computeLogRecordOperations(method, targetClass);
List<String> spElTemplates = getBeforeExecuteFunctionTemplate(operations);
//业务逻辑执行前的自定义函数解析
functionNameAndReturnMap = processBeforeExecuteFunctionTemplate(spElTemplates, targetClass, method, args);
} catch (Exception e) {
log.error("log record parse before function exception", e);
}
try {
ret = invoker.proceed();
} catch (Exception e) {
methodExecuteResult = new MethodExecuteResult(false, e, e.getMessage());
}
try {
if (!CollectionUtils.isEmpty(operations)) {
recordExecute(ret, method, args, operations, targetClass,
methodExecuteResult.isSuccess(), methodExecuteResult.getErrorMsg(), functionNameAndReturnMap);
}
} catch (Exception t) {
//记录日志错误不要影响业务
log.error("log record parse exception", t);
} finally {
LogRecordContext.clear();
}
if (methodExecuteResult.throwable != null) {
throw methodExecuteResult.throwable;
}
return ret;
}

拦截逻辑的流程:

img

可以看到,操作日志的记录持久化是在方法执行完之后执行的,当方法抛出异常之后会先捕获异常,等操作日志持久化完成后再抛出异常。在业务的方法执行之前,会对提前解析的自定义函数求值,解决了前面提到的需要查询修改之前的内容。

4.2.2 解析逻辑

模板解析

Spring 3 提供了一个非常强大的功能:Spring EL,SpEL 在 Spring 产品中是作为表达式求值的核心基础模块,它本身是可以脱离 Spring 独立使用的。举个例子:

1
2
3
4
5
6
7
public static void main(String[] args) {
SpelExpressionParser parser = new SpelExpressionParser();
Expression expression = parser.parseExpression("#root.purchaseName");
Order order = new Order();
order.setPurchaseName("张三");
System.out.println(expression.getValue(order));
}

这个方法将打印 “张三”。LogRecord 解析的类图如下:

img

解析核心类LogRecordValueParser 里面封装了自定义函数和 SpEL 解析类 LogRecordExpressionEvaluator

1
2
3
4
5
6
7
8
9
10
public class LogRecordExpressionEvaluator extends CachedExpressionEvaluator {

private Map<ExpressionKey, Expression> expressionCache = new ConcurrentHashMap<>(64);

private final Map<AnnotatedElementKey, Method> targetMethodCache = new ConcurrentHashMap<>(64);

public String parseExpression(String conditionExpression, AnnotatedElementKey methodKey, EvaluationContext evalContext) {
return getExpression(this.expressionCache, methodKey, conditionExpression).getValue(evalContext, String.class);
}
}

LogRecordExpressionEvaluator 继承自 CachedExpressionEvaluator 类,这个类里面有两个 Map,一个是 expressionCache 一个是 targetMethodCache。在上面的例子中可以看到,SpEL 会解析成一个 Expression 表达式,然后根据传入的 Object 获取到对应的值,所以 expressionCache 是为了缓存方法、表达式和 SpEL 的 Expression 的对应关系,让方法注解上添加的 SpEL 表达式只解析一次。 下面的 targetMethodCache 是为了缓存传入到 Expression 表达式的 Object。核心的解析逻辑是上面最后一行代码。

1
getExpression(this.expressionCache, methodKey, conditionExpression).getValue(evalContext, String.class);

getExpression 方法会从 expressionCache 中获取到 @LogRecordAnnotation 注解上的表达式的解析 Expression 的实例,然后调用 getValue 方法,getValue 传入一个 evalContext 就是类似上面例子中的 order 对象。其中 Context 的实现将会在下文介绍。

日志上下文实现

下面的例子把变量放到了 LogRecordContext 中,然后 SpEL 表达式就可以顺利的解析方法上不存在的参数了,通过上面的 SpEL 的例子可以看出,要把方法的参数和 LogRecordContext 中的变量都放到 SpEL 的 getValue 方法的 Object 中才可以顺利的解析表达式的值。下面看下如何实现:

1
2
3
4
5
6
7
8
@LogRecord(content = "修改了订单的配送员:从“{deveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.getUserId()}}”",
bizNo="#request.getDeliveryOrderNo()")
public void modifyAddress(updateDeliveryRequest request){
// 查询出原来的地址是什么
LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

在 LogRecordValueParser 中创建了一个 EvaluationContext,用来给 SpEL 解析方法参数和 Context 中的变量。相关代码如下:

1
EvaluationContext evaluationContext = expressionEvaluator.createEvaluationContext(method, args, targetClass, ret, errorMsg, beanFactory);

在解析的时候调用 getValue 方法传入的参数 evalContext,就是上面这个 EvaluationContext 对象。下面是 LogRecordEvaluationContext 对象的继承体系:

img

LogRecordEvaluationContext 做了三个事情: * 把方法的参数都放到 SpEL 解析的 RootObject 中。 * 把 LogRecordContext 中的变量都放到 RootObject 中。 * 把方法的返回值和 ErrorMsg 都放到 RootObject 中。

LogRecordEvaluationContext 的代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public class LogRecordEvaluationContext extends MethodBasedEvaluationContext {

public LogRecordEvaluationContext(Object rootObject, Method method, Object[] arguments,
ParameterNameDiscoverer parameterNameDiscoverer, Object ret, String errorMsg) {
//把方法的参数都放到 SpEL 解析的 RootObject 中
super(rootObject, method, arguments, parameterNameDiscoverer);
//把 LogRecordContext 中的变量都放到 RootObject 中
Map<String, Object> variables = LogRecordContext.getVariables();
if (variables != null && variables.size() > 0) {
for (Map.Entry<String, Object> entry : variables.entrySet()) {
setVariable(entry.getKey(), entry.getValue());
}
}
//把方法的返回值和 ErrorMsg 都放到 RootObject 中
setVariable("_ret", ret);
setVariable("_errorMsg", errorMsg);
}
}

下面是 LogRecordContext 的实现,这个类里面通过一个 ThreadLocal 变量保持了一个栈,栈里面是个 Map,Map 对应了变量的名称和变量的值。

1
2
3
4
5
public class LogRecordContext {

private static final InheritableThreadLocal<Stack<Map<String, Object>>> variableMapStack = new InheritableThreadLocal<>();
//其他省略....
}

上面使用了 InheritableThreadLocal,所以在线程池的场景下使用 LogRecordContext 会出现问题,如果支持线程池可以使用阿里巴巴开源的 TTL 框架。那这里为什么不直接设置一个 ThreadLocal> 对象,而是要设置一个 Stack 结构呢?我们看一下这么做的原因是什么。

1
2
3
4
5
6
7
8
@LogRecord(content = "修改了订单的配送员:从“{deveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.getUserId()}}”",
bizNo="#request.getDeliveryOrderNo()")
public void modifyAddress(updateDeliveryRequest request){
// 查询出原来的地址是什么
LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
// 更新派送信息 电话,收件人、地址
doUpdate(request);
}

上面代码的执行流程如下:

img

看起来没有什么问题,但是使用 LogRecordAnnotation 的方法里面嵌套了另一个使用 LogRecordAnnotation 方法的时候,流程就变成下面的形式:

img

可以看到,当方法二执行了释放变量后,继续执行方法一的 logRecord 逻辑,此时解析的时候 ThreadLocal>的 Map 已经被释放掉,所以方法一就获取不到对应的变量了。方法一和方法二共用一个变量 Map 还有个问题是:如果方法二设置了和方法一相同的变量两个方法的变量就会被相互覆盖。所以最终 LogRecordContext 的变量的生命周期需要是下面的形式:

img

LogRecordContext 每执行一个方法都会压栈一个 Map,方法执行完之后会 Pop 掉这个 Map,从而避免变量共享和覆盖问题。

默认操作人逻辑

在 LogRecordInterceptor 中 IOperatorGetService 接口,这个接口可以获取到当前的用户。下面是接口的定义:

1
2
3
4
5
6
7
8
9
public interface IOperatorGetService {

/**
* 可以在里面外部的获取当前登陆的用户,比如 UserContext.getCurrentUser()
*
* @return 转换成Operator返回
*/
Operator getUser();
}

下面给出了从用户上下文中获取用户的例子:

1
2
3
4
5
6
7
8
9
10
11
public class DefaultOperatorGetServiceImpl implements IOperatorGetService {

@Override
public Operator getUser() {
//UserUtils 是获取用户上下文的方法
return Optional.ofNullable(UserUtils.getUser())
.map(a -> new Operator(a.getName(), a.getLogin()))
.orElseThrow(()->new IllegalArgumentException("user is null"));

}
}

组件在解析 operator 的时候,就判断注解上的 operator 是否是空,如果注解上没有指定,我们就从 IOperatorGetService 的 getUser 方法获取了。如果都获取不到,就会报错。

1
2
3
4
5
6
7
8
9
String realOperatorId = "";
if (StringUtils.isEmpty(operatorId)) {
if (operatorGetService.getUser() == null || StringUtils.isEmpty(operatorGetService.getUser().getOperatorId())) {
throw new IllegalArgumentException("user is null");
}
realOperatorId = operatorGetService.getUser().getOperatorId();
} else {
spElTemplates = Lists.newArrayList(bizKey, bizNo, action, operatorId, detail);
}
自定义函数逻辑

自定义函数的类图如下:

img

下面是 IParseFunction 的接口定义:executeBefore 函数代表了自定义函数是否在业务代码执行之前解析,上面提到的查询修改之前的内容。

1
2
3
4
5
6
7
8
9
10
public interface IParseFunction {

default boolean executeBefore(){
return false;
}

String functionName();

String apply(String value);
}

ParseFunctionFactory 的代码比较简单,它的功能是把所有的 IParseFunction 注入到函数工厂中。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
public class ParseFunctionFactory {
private Map<String, IParseFunction> allFunctionMap;

public ParseFunctionFactory(List<IParseFunction> parseFunctions) {
if (CollectionUtils.isEmpty(parseFunctions)) {
return;
}
allFunctionMap = new HashMap<>();
for (IParseFunction parseFunction : parseFunctions) {
if (StringUtils.isEmpty(parseFunction.functionName())) {
continue;
}
allFunctionMap.put(parseFunction.functionName(), parseFunction);
}
}

public IParseFunction getFunction(String functionName) {
return allFunctionMap.get(functionName);
}

public boolean isBeforeFunction(String functionName) {
return allFunctionMap.get(functionName) != null && allFunctionMap.get(functionName).executeBefore();
}
}

DefaultFunctionServiceImpl 的逻辑就是根据传入的函数名称 functionName 找到对应的 IParseFunction,然后把参数传入到 IParseFunction 的 apply 方法上最后返回函数的值。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
public class DefaultFunctionServiceImpl implements IFunctionService {

private final ParseFunctionFactory parseFunctionFactory;

public DefaultFunctionServiceImpl(ParseFunctionFactory parseFunctionFactory) {
this.parseFunctionFactory = parseFunctionFactory;
}

@Override
public String apply(String functionName, String value) {
IParseFunction function = parseFunctionFactory.getFunction(functionName);
if (function == null) {
return value;
}
return function.apply(value);
}

@Override
public boolean beforeFunction(String functionName) {
return parseFunctionFactory.isBeforeFunction(functionName);
}
}
4.2.3 日志持久化逻辑

同样在 LogRecordInterceptor 的代码中引用了 ILogRecordService,这个 Service 主要包含了日志记录的接口。

1
2
3
4
5
6
7
8
9
public interface ILogRecordService {
/**
* 保存 log
*
* @param logRecord 日志实体
*/
void record(LogRecord logRecord);

}

业务可以实现这个保存接口,然后把日志保存在任何存储介质上。这里给了一个 2.2 节介绍的通过 log.info 保存在日志文件中的例子,业务可以把保存设置成异步或者同步,可以和业务放在一个事务中保证操作日志和业务的一致性,也可以新开辟一个事务,保证日志的错误不影响业务的事务。业务可以保存在 Elasticsearch、数据库或者文件中,用户可以根据日志结构和日志的存储实现相应的查询逻辑。

1
2
3
4
5
6
7
8
9
@Slf4j
public class DefaultLogRecordServiceImpl implements ILogRecordService {

@Override
// @Transactional(propagation = Propagation.REQUIRES_NEW)
public void record(LogRecord logRecord) {
log.info("【logRecord】log={}", logRecord);
}
}
4.2.4 Starter 逻辑封装

上面逻辑代码已经介绍完毕,那么接下来需要把这些组件组装起来,然后让用户去使用。在使用这个组件的时候只需要在 Springboot 的入口上添加一个注解 @EnableLogRecord(tenant = “com.mzt.test”)。其中 tenant 代表租户,是为了多租户使用的。

1
2
3
4
5
6
7
8
9
@SpringBootApplication(exclude = DataSourceAutoConfiguration.class)
@EnableTransactionManagement
@EnableLogRecord(tenant = "com.mzt.test")
public class Main {

public static void main(String[] args) {
SpringApplication.run(Main.class, args);
}
}

再看下 EnableLogRecord 的代码,代码中 Import 了 LogRecordConfigureSelector.class,在 LogRecordConfigureSelector 类中暴露了 LogRecordProxyAutoConfiguration 类。

1
2
3
4
5
6
7
8
9
10
@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Import(LogRecordConfigureSelector.class)
public @interface EnableLogRecord {

String tenant();

AdviceMode mode() default AdviceMode.PROXY;
}

LogRecordProxyAutoConfiguration 就是装配上面组件的核心类了,代码如下:

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
@Configuration
@Slf4j
public class LogRecordProxyAutoConfiguration implements ImportAware {

private AnnotationAttributes enableLogRecord;


@Bean
@Role(BeanDefinition.ROLE_INFRASTRUCTURE)
public LogRecordOperationSource logRecordOperationSource() {
return new LogRecordOperationSource();
}

@Bean
@ConditionalOnMissingBean(IFunctionService.class)
public IFunctionService functionService(ParseFunctionFactory parseFunctionFactory) {
return new DefaultFunctionServiceImpl(parseFunctionFactory);
}

@Bean
public ParseFunctionFactory parseFunctionFactory(@Autowired List<IParseFunction> parseFunctions) {
return new ParseFunctionFactory(parseFunctions);
}

@Bean
@ConditionalOnMissingBean(IParseFunction.class)
public DefaultParseFunction parseFunction() {
return new DefaultParseFunction();
}


@Bean
@Role(BeanDefinition.ROLE_INFRASTRUCTURE)
public BeanFactoryLogRecordAdvisor logRecordAdvisor(IFunctionService functionService) {
BeanFactoryLogRecordAdvisor advisor =
new BeanFactoryLogRecordAdvisor();
advisor.setLogRecordOperationSource(logRecordOperationSource());
advisor.setAdvice(logRecordInterceptor(functionService));
return advisor;
}

@Bean
@Role(BeanDefinition.ROLE_INFRASTRUCTURE)
public LogRecordInterceptor logRecordInterceptor(IFunctionService functionService) {
LogRecordInterceptor interceptor = new LogRecordInterceptor();
interceptor.setLogRecordOperationSource(logRecordOperationSource());
interceptor.setTenant(enableLogRecord.getString("tenant"));
interceptor.setFunctionService(functionService);
return interceptor;
}

@Bean
@ConditionalOnMissingBean(IOperatorGetService.class)
@Role(BeanDefinition.ROLE_APPLICATION)
public IOperatorGetService operatorGetService() {
return new DefaultOperatorGetServiceImpl();
}

@Bean
@ConditionalOnMissingBean(ILogRecordService.class)
@Role(BeanDefinition.ROLE_APPLICATION)
public ILogRecordService recordService() {
return new DefaultLogRecordServiceImpl();
}

@Override
public void setImportMetadata(AnnotationMetadata importMetadata) {
this.enableLogRecord = AnnotationAttributes.fromMap(
importMetadata.getAnnotationAttributes(EnableLogRecord.class.getName(), false));
if (this.enableLogRecord == null) {
log.info("@EnableCaching is not present on importing class");
}
}
}

这个类继承 ImportAware 是为了拿到 EnableLogRecord 上的租户属性,这个类使用变量 logRecordAdvisor 和 logRecordInterceptor 装配了 AOP,同时把自定义函数注入到了 logRecordAdvisor 中。

对外扩展类:分别是IOperatorGetServiceILogRecordServiceIParseFunction。业务可以自己实现相应的接口,因为配置了 @ConditionalOnMissingBean,所以用户的实现类会覆盖组件内的默认实现。

  1. 总结

这篇文章介绍了操作日志的常见写法,以及如何让操作日志的实现更加简单、易懂;通过组件的四个模块,介绍了组件的具体实现。对于上面的组件介绍,大家如果有疑问,也欢迎在文末留言,我们会进行答疑。

  1. 作者简介

站通,2020年加入美团,基础研发平台/研发质量及效率部工程师。

  1. 参考资料

美团高性能终端日志

1 背景

1.1 Logan 简介

Logan 是美团面向终端的统一日志服务,已支持移动端App、Web、小程序、IoT等多端环境,具备日志采集、存储、上传、查询与分析等能力,帮助用户定位研发问题,提升故障排查效率。同时,Logan 也是业内开源较早的大前端日志系统,具有写入性能高、安全性高、日志防丢失等优点。

1.2 Logan 工作流程

为了方便读者更好地理解 Logan 系统是如何工作的,下图是简化后的 Logan 系统工作流程图。主要分为以下几个部分:

  • 主动上报日志:终端设备在需要上报日志时,可以通过 HTTPS 接口主动上传日志到 Logan 接收服务,接收服务再把原始日志文件转存到对象存储平台。
  • 日志解密与解析:当研发人员想要查看主动上报的日志时会触发日志下载与解析流程,原始加密日志从对象存储平台下载成功后进行解密、解析等操作,然后再投递到日志存储系统。
  • 日志查询与检索:日志平台支持对单设备所有日志进行日志类型、标签、进程、关键字、时间等维度的筛选,同时也支持对一些特定类型的日志进行可视化展示。

图1 Logan 系统工作流程图

图1 Logan 系统工作流程图

1.3 为什么需要实时日志?

如前文所述,这套“本地存储+主动上报”的模式虽然解决了大前端场景下基础的日志使用需求,但是随着业务复杂度的不断增加,用户对日志的要求也越来越高,当前 Logan 架构存在的问题也变得越来越突出,主要体现在以下几个方面:

  1. 部分场景上报日志受限:由于在 Web 与小程序上用户一般的使用场景是用完即走,当线上出现问题时再联系用户主动上报日志,整个处理周期较长,有可能会错过最佳排查时间。
  2. 缺少实时分析和告警能力:当前缺少实时分析和告警的能力,用户曾多次提到过想要对线上异常日志进行监控,当有符合规则的异常日志出现时能收到告警信息。
  3. 缺少全链路追踪能力:当前多端的日志散落在各个系统中,研发人员在定位问题时需要手动去关联日志,操作起来很不方便,美团内部缺乏一个通用的全链路追踪方案。

针对以上痛点问题,我们提出了建设 Logan 实时日志,旨在提供统一的、高性能的实时日志服务,以解决美团现阶段不同业务系统想要日志上云的需求。

1.4 Logan 实时日志是什么?

Logan 实时日志是服务于移动端 App、Web、小程序、IoT 等终端场景下的实时日志解决方案,旨在提供高扩展性、高性能、高可靠性的实时日志服务,包括日志采集、上传、加工、消费、投递、查询与分析等能力。

图2 Logan 实时日志产品功能图

图2 Logan 实时日志产品功能图

2 设计实现

2.1 整体架构

图3 Logan 实时日志整体架构图

图3 Logan 实时日志整体架构图

如上图所示,整体架构主要分为五个部分,它们分别是:

  • 采集端:负责端上日志数据的采集、加密、压缩、聚合和上报等。
  • 接入层:负责提供日志上报接口,接收日志上报数据,并将数据转发到数据处理层。
  • 数据处理层:负责日志数据的解密、拆分、加工和清洗等。
  • 数据消费层:负责日志数据的过滤、格式化、投递等。
  • 日志平台:负责日志数据查询与分析、业务系统接入配置、统计与告警等。

2.2 采集端

通用采集端架构,解决跨平台复用

采集端SDK用于端侧日志收集,需要在多种终端环境落地,但是由于端和平台较多、技术栈和运行环境也不一致,多端开发和维护成本会比较高。因此,我们设计了一套核心逻辑复用的通用采集端架构,具体的平台依赖代码则单独进行适配。我们目前上线了微信、MMP、Web、MRN 端侧,逻辑层代码做到了完全复用。采集端架构设计图如下:

图4 采集端SDK架构图

图4 采集端SDK架构图

重点模块介绍:

  • 配置管理:采集端初始化完成后,首先启动配置管理模块,拉取和刷新配置信息,包括上报限流配置、指标采样率、功能开关等,支持对关键配置进行灰度发布。
  • 加密:所有记录的日志都使用 ECDH + AES 方案加密,确保日志信息不泄漏。Web 版加密模块使用浏览器原生加密 API 进行适配,可实现高性能异步加密,其他平台则使用纯 JS 实现。
  • 存储管理:线上数据表明,由于页面关闭导致的日志丢失占比高达 1%,因此我们设计了日志落盘功能,当日志上传失败后会先缓存在本地磁盘,等到页面下一次启动时再重新恢复上传。
  • 队列管理:需要发送的日志首先进行分组聚合,如果等待分组过多则需要丢弃一部分请求,防止在弱网环境或者日志堆积太多时造成内存持续上涨而影响用户。

落盘缓存 + 上报恢复,防止日志丢失

为了方便读者更好地理解端上日志采集过程,下面将具体介绍下采集端流程设计。当采集端初始化 API 开始调用时,先创建 Logger、Encryptor、Storage 等实例对象,并异步拉取环境配置文件。初始化完成之后,先检查是否有成功落盘,但是上报失败的日志,如果有的话立即开始恢复上传流程。当正常调用写日志 API 时,原始日志被加密后加入当前上报组,等到有上报事件(时间、条数、导航等)触发时,当前上报组内的所有日志被加入上报队列并开始上传。采集端详细流程图如下:

图5 采集端SDK流程图

图5 采集端SDK流程图

2.3 数据接入层

对于实时日志系统来讲,接入层需要满足以下几点要求:(1)支持公网上报域名;(2)支持高并发处理;(3)具备高实时性,延迟是分钟级;(4)支持投递数据到 Kafka 消息队列。

经过对比,美团内的统一日志收集通道均满足以上需求,因此我们选用了统一日志收集通道作为接入层。采集端SDK通过独立的公网域名上报日志后,收集通道将日志数据汇总好并投递到指定的Kafka消息队列。如果读者公司没有类似的日志收集通道,那么可以参考以下流程搭建实时日志系统接入层。

图6 接入层流程图

图6 接入层流程图

2.4 数据处理层

在数据处理框架的技术选型上,我们先后考虑了三种方案,分别是传统架构(Java 应用)、Storm 架构、Flink 架构,这三种方案在不同维度的对比数据如下:

方案 成熟度 稳定性 扩展性 容错性 延迟 吞吐量 开发成本 运维成本
传统架构
Storm 架构
Flink 架构

表1 技术选型对比表

综合来看,虽然传统架构有比较好的成熟度与灵活性,但是在扩展性、容错性以及性能上均不能满足系统要求,而 Flink 架构与 Storm 架构都有比较优秀的扩展性与容错性,但是 Flink 架构在延迟与吞吐量上表现要更好,因此我们最终选择了使用 Flink 架构作为数据处理框架。

Flink:业内领先的流式计算引擎,具有高吞吐、低延迟、高可靠和精确计算等优点,对事件窗口有很好的支持,被业内很多公司作为首选的流式计算引擎。

在日志处理流程设计上,日志数据通过接入层处理后被投递到汇总 topic 里面,然后再通过 Flink 作业的逻辑处理后分发到下游。处理流程如下图所示:

图7 日志处理层流程图

图7 日志处理层流程图

汇总后的日志数据处理和分发依赖于实时计算平台的实时作业能力,底层使用 Flink 数据处理引擎,主要负责日志数据的解析、日志内容的解密以及拆分到下游等。

  1. 元数据解析:通过实时作业能力完成原始日志数据解析为 JSON 对象数据。
  2. 内容解密:对加密内容进行解密,此处使用非对称协商计算出对称加密密钥,然后再进行解密。
  3. 服务维度拆分:通过 topic 字段把日志分发到各业务系统所属的 topic 里面,从而实现业务日志相互隔离。
  4. 数据自定义加工:根据用户自定义的加工语法模版,从服务 topic 实时消费并加工数据到自定义 topic 中。

2.5 数据消费层

对大部分用户来说 Logan 实时日志提供的日志采集、加工、检索能力已经能满足大部分需求。但是在与用户沟通过程中我们发现还有一些更高阶的需求,比如指标监控、前后端链路串联、离线数据计算等。于是我们将 Logan 标准化后的日志统一投递到 Kafka 流处理平台,并提供一些通用的数据转换能力,方便用户按需接入到不同的第三方系统。数据消费层设计如下图所示:

图8 数据消费层设计图

图8 数据消费层设计图

数据消费层的一些典型的应用场景:

  1. 网络全链路追踪:现阶段前后端的日志可能分布在不同的系统中,前端日志系统记录的主要是代码级日志、端到端日志等,后端日志系统记录的是链路关系、服务耗时等信息。通过 Logan 实时日志开放的数据消费能力,用户可以根据自己的需求来串联多端日志,从而实现网络全链路追踪。
  2. 指标聚合统计&告警:实时日志也是一种实时的数据流,可以作为指标数据上报的载体,如果把日志数据对接到数据统计平台就能实现指标监控和告警了。
  3. 离线数据分析:如果在一些需求场景下需要对数据进行长期化保存或者离线分析,就可以将数据导入到 Hive 中来实现。

2.6 日志平台

日志平台的核心功能是为用户提供日志检索支持,日志平台提供了用户标识、自定义标签、关键字等多种检索过滤方式。在日志底层存储架构的选择上,目前业界广泛使用的是 Elasticsearch,考虑到计费与运维成本的关系,美团内部已经有一套统一的框架可以使用,所以我们也选用了 Elasticsearch 架构。同时,我们也支持通过单独的接口层适配其他存储引擎,日志查询流程如下:

图9 日志查询流程设计图

图9 日志查询流程设计图

Elasticsearch:是一个分布式的开源搜索和分析引擎,具有接入成本低、扩展性高和近实时性等优点,比较适合用来做大数据量的全文检索服务,例如日志查询等。

3 稳定性保障

3.1 核心监控

为了衡量终端实时日志系统的可用性,我们制定了以下核心 SLA 指标:

指标名称 指标定义 目标
端侧上报成功率 端侧日志上报请求成功次数 / 上报请求总次数 99.5%
服务可用性 服务周期内系统可用时长 / 服务周期总时长 99.9%
日志平均延迟 日志从产生到可以被消费的平均延迟时长 < 1 min

表2 核心 SLA 指标表格

除了核心指标监控之外,我们还建设了全流程监控大盘,覆盖了分端上报成功率、域名可用性、域名 QPS、作业吞吐量、平均聚合条数等重要观测指标,并且针对上报成功率、域名 QPS、作业吞吐量等配置了兜底告警,当线上有异常时可以第一时间发现并进行处理。

3.2 蓝绿发布

实时日志依赖于实时作业的处理计算能力,但是目前实时作业的发布和部署不能无缝衔接,中间可能存在真空的情况。当重启作业时,需要先停止原作业,再启动新的作业。如果遇到代码故障或系统资源不足等情况时则会导致作业启动失败,从而直接面临消息积压严重和数据延时升高的问题,这对于实时日志系统来说是不能忍受的。

蓝绿发布(Blue Green Deployment)是一种平滑过渡的发布模式。在蓝绿发布模式中,首先要将应用划分为对等的蓝绿两个分组,蓝组发布新产品代码并引入少许线上流量,绿组继续运行老产品代码。当新产品代码经线上运行观察没有问题后,开始逐步引入更多线上流量,直至所有流量都访问蓝组新产品。因此,蓝绿发布可以保证整体系统的稳定,在产品发布前期就可以发现并解决问题,以保证其影响面可控。

目前美团已有的实时作业蓝绿部署方案各不相同,由于 Logan 实时日志接入业务系统较多,且数据量较大,经过综合考量后,我们决定自己实现一套适合当前系统的蓝绿部署方案。为了保证系统的稳定性,在作业运行过程中,启动另外一个相同的作业,当新作业运行没有问题后,再完成新老作业切换。蓝绿发布流程图如下:

图10 蓝绿发布流程图

图10 蓝绿发布流程图

使用蓝绿部署后,彻底解决了由于资源不足或参数不对导致的上线失败问题,平均部署切换耗时也保持在1分钟以内,基本避免了因发布带来的日志消费延迟问题。

4 落地成果

Logan 实时日志在建设初期就受到了各个业务的广泛关注,截止到 2022 年第 3 季度,Logan 实时日志接入并上线的业务系统数量已多达二十余个,其中包括美团小程序、优选商家、餐饮 SaaS 等大体量业务。下面是一些业务系统接入的典型使用场景,供大家参考:

  1. 核心链路还原:到家某 C 端小程序使用 Logan 实时日志记录程序核心链路中的关键日志与异常日志,当线上有客诉问题发生时,可以第一时间查看实时日志并定位问题。项目上线后,平均客诉定位时间从之前的 10 分钟减少到 3 分钟以内,排障效率有明显提升。
  2. 内测阶段排障:企业平台某前端项目由于 2.0 改版改动较大,于是使用 Logan 实时日志在内测阶段添加更多的调试日志,方便定位线上问题。项目上线后,每次排查问题除了节省用户上报日志时间 10-15 分钟,还杜绝了因为存储空间不足而拿不到用户日志的情况。
  3. 日志数据分析:美团到店某团队使用 Logan 实时日志分析前后端交互过程中的请求头、请求参数、响应体等数据是否符合标准化规范。经过一个多月时间的试运行,一期版本上线后共覆盖 300+ 前端页面和 500+ 前端接口,共计发现 1000+ 规范问题。

5 未来规划

Logan 实时日志经过半年的建设与推广,已经完成了系统基础能力的建设,能满足用户对于实时日志的基本诉求。但是对于日志数据深加工与清洗、日志统计与告警等高阶需求还不支持,因此为了更好地发挥日志价值,提升终端故障排查效率,Logan 实时日志有以下几个方面的规划:

  • 完善功能:支持更多终端类型,建设日志加工与清洗、日志统计与告警、全链路追踪等功能。
  • 提升性能:支持百万并发QPS、日志上报成功率提升至 99.9% 等。
  • 提升稳定性:建设限流熔断机制、应急响应与故障处理预案等。