How to record operation logs gracefully?

Operation logs are widely available in various B-side and some C-side systems. For example, customer service can quickly know who has done what operations on the work order according to the operation log of the work order, and then quickly locate the problem. The operation log is not the same as the system log. The operation log must be simple and easy to understand. So how to make the operation log not coupled with the business logic, how to make the content of the operation log easy to understand, and make the access of the operation log easier? The above are the questions to be answered in this article, mainly centered on how to "gracefully" record the operation log to expand the description.

1. Usage scenarios of operation logs

The difference between system log and operation log

System log : The system log is mainly to provide a basis for development and troubleshooting, and is generally printed in a log file; the readability of the system log is not so demanding, and the log will contain code information, such as a certain line in a certain category A log was printed.

Operation log : Mainly to record this addition or modification after adding or modifying an object. The operation log requires strong readability, because it is mainly for users to see, such as order logistics information , The user needs to know what happened at what time. For another example, customer service records information about the processing of work orders.

The record format of the operation log is roughly divided into the following types:

• Pure text records, such as: 2021-09-16 10:00 order creation.
• Simple dynamic text record, such as: 2021-09-16 10:00 order creation, order number: NO.11089999, which involves variable order number "NO.11089999".
• The text of the modification type, including the values before and after modification, such as: 2021-09-16 10:00 The user Xiaoming modified the delivery address of the order: from "Jincancan Community" to "Yinzhanzhan Community", which involves variables The original delivery address is "Jincancan Community" and the new address is "Yinzhanzhan Community".
• Modifying the form will modify multiple fields at once.

2. Implementation

2.1 Use Canal to monitor database to record operation logs

Canal is an open source component based on MySQL database incremental log analysis that provides incremental data subscription and consumption. By monitoring the database Binlog, you can know from the bottom what data has been modified, and then record operations based on the changed data Log.

The advantage of this approach is that it is completely separated from the business logic. The shortcomings are also obvious. The limitations are too high. You can only log the changes to the database. If the modification involves RPC calls from other teams, there is no way to monitor the database. For example: send notifications to users and notify the service Generally, they are internal public components of the company. At this time, you can only manually record the operation log of sending notifications when calling RPC.

2.2 Record by way of log files

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

There are three problems to be solved for the operation record in this way.

Question 1: How does the operator record

With the help of MDC tools in SLF4J, put the operator in the log, and then print it out in the log. First put the user's identity into the MDC in the user's interceptor.

@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;
  }
}

Second, format the userId into the log, and use %X{userId} to get the user ID in the MDC.

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

Question 2: How to distinguish the operation log from the system log

By configuring the Log configuration file, the Log related to the operation log is separately placed in a log file.

//不同业务日志记录到不同的文件
<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>

Then record the business log separately in the Java code.

//记录特定日志的声明
private final Logger businessLog = LoggerFactory.getLogger("businessLog");
 
//日志存储
businessLog.info("修改了配送地址");

Question 3: How to generate

You can use the LogUtil method, or you can use the aspect method to generate the log template, which will be introduced later. In this way, the log can be saved in a file separately, and then the log can be saved in Elasticsearch or a database through log collection. Next, let's see how to generate a readable operation log.

2.3 Record logs by way of LogUtil

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

Here is an explanation of why an OrderNo is bound to the operation log, because the operation log records: a certain "time" and "who" did what "thing" to "what". When querying the operation log of the business, it will query all operations for this order, so OrderNo is added to the code. When recording the operation log, the operator needs to be recorded, so the operator "Xiao Ming" is passed in.

The problem above does not seem to be a big problem. In the business logic method of modifying the address, a line of code is used to record the operation log. Next, let's look at a more complicated example:

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);
}

You can see that the above example uses two method codes, plus a getLogContent function to achieve operation log recording. When the business becomes complex, putting the operation log in the business code will cause the business logic to be more complicated, and finally cause the LogUtils.logRecord() method to be called in many business codes, and methods like getLogContent() are also Scattered in various business classes is a disaster for the readability and maintainability of the code. Here's how to avoid this disaster.

2.4 Method annotation to achieve operation log

In order to solve the above problems, AOP is generally used to record logs to decouple the operation log and business logic. Next, let's look at a simple AOP log example.

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

We can record fixed copy in the annotated operation log, so that business logic and business code can be decoupled, and our business code becomes pure. Some students may have noticed that although the above method decouples the code of the operation log, the recorded copy does not meet our expectations. The copy is static and does not contain dynamic copy, because the operation log we need to record is: User %s modified the delivery address of the order from "%s" to "%s". Next, we introduce how to use AOP elegantly to generate dynamic operation logs.

3. Elegantly support AOP to generate dynamic operation logs

3.1 Dynamic template

When it comes to dynamic templates, it involves letting variables parse the template through placeholders, so as to achieve the purpose of recording operation logs through annotations. There are many ways of template parsing, and SpEL (Spring Expression Language, Spring Expression Language) is used here. We can first write down the desired logging method, and then see if such a function can be achieved.

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

By using SpEL expressions to reference parameters on the method, variables can be filled into the template to achieve dynamic operation log text content.
But there are still several issues that need to be resolved:

• The operation log needs to know which operator modified the order delivery address.
• The operation log for modifying the delivery address of an order needs to be bound to the delivery order, so that all operations on this delivery order can be queried according to the delivery order number.
• In order to record the previous delivery address in the annotation, an oldAddress variable that has nothing to do with the business is added to the method signature, which is not elegant.

In order to solve the first two problems, we need to change the expected operation log usage form to the following way:

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

The modified code adds two parameters to the annotation, one is the operator, and the other is the object to be bound to the operation log. However, in ordinary Web applications, user information is stored in a static method of a thread context, so operator is generally written in this way (assuming that the way to get the currently logged-in user is UserContext.getCurrentUser()).

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

In this case, the operator on each @LogRecord annotation is such a long string. In order to avoid too much code repetition, we can set the operator parameter on the annotation to be optional, so that the user can fill in the operator. However, if the user does not fill in, we will take the user of the UserContext (how to take user will be described below). Finally, the simplest log becomes the following form:

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

Next, we need to solve the third problem: In order to record the business operation record, an oldAddress variable is added, which is not a good way to implement it anyway, so next, we need to change the oldAddress variable from the signature of the method to modify the address Get rid of. But the operation log does require the oldAddress variable, what should I do?

Either PK with the product manager and ask the product manager to change the copy from "modified order delivery address: from xx to yy" to "modified order delivery address: yy". But from the user experience point of view, the first type of copywriting is more humane, and obviously we will not succeed in PK. Then we have to query this oldAddress and use it for the operation log. Another solution is to put this parameter in the thread context of the operation log for use by the template on the annotation. Let's change the implementation code of the operation log according to this idea.

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

At this time, it can be seen that LogRecordContext solves the problem of using variables other than method parameters on the operation log template, and at the same time avoids the design of modifying the method signature to record the operation log. Although it is better than the previous code, it is still necessary to add a line of business logic irrelevant code to the business code. If you have "obsessive-compulsive disorder" students can continue to look down, and then we will explain the custom function solution. Let's look at another example:

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

The last recorded content of this operation log template is in this format: The delivery person who has modified the order: from "10090" to "10099". Obviously, the user does not understand this operation log. The user does not know whether the user ID is 10090 or 10099. What the user expects to see is: the delivery person who has modified the order: from "Zhang San (18910008888)" to "Xiao Ming (13910006666)". What the user cares about is the name and phone number of the delivery person. But the parameter passed in our method is only the ID of the dispatcher, and there is no name for the dispatcher to call. We can query the user's name and phone number through the above method, and then implement it through LogRecordContext.

However, "obsessive-compulsive disorder" does not expect the code of the operation log to be embedded in the business logic. Next, we consider another implementation: custom function. If we can convert the user ID to the user name and phone number through a custom function, then this problem can be solved. According to this idea, we modify the template to the following form:

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

Among them, deliveryUser is a custom function. Use curly braces to wrap Spring's SpEL expression. The advantages of this are: First, it separates SpEL (Spring Expression Language) from custom functions for easy analysis; second, if SpEL expression analysis is not needed in the template, which can be easily identified, reducing the analysis of SpEL and improving performance. At this time, we found that the above code can also be optimized into the following form:

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

In this way, there is no need to set the old courier through LogRecordContext.putVariable() in the modifyAddress method. By directly adding a new custom function queryOldUser() parameter to pass the delivery order in, you can find the previous courier, only The method's resolution needs to be run before the modifyAddress() method is executed. In this case, we make the business code pure again, and at the same time make the "obsessive-compulsive disorder" no longer uncomfortable.

4. Code implementation analysis

4.1 Code structure

The above operation log is mainly realized through an AOP interceptor, and the whole is mainly divided into AOP module, log analysis module, log saving module, and Starter module; the component provides 4 extension points, namely: custom function, default handler , Business storage and query; business can be customized according to their own business characteristics in line with their own business logic.

4.2 Module introduction

With the above analysis, we have come up with a way of operation log recording we expect, so let's take a look at how to implement the above logic. The realization is mainly divided into the following steps:

• AOP interception logic

• Parsing logic

  • Template analysis
  • LogContext logic
  • Default operator logic
  • Custom function logic
• The default log persistence logic
• Starter packaging logic

4.2.1 AOP interception logic

This piece of logic is mainly an interceptor, which analyzes the operation log that needs to be recorded for the @LogRecord annotation, and then persists the operation log. Here, the annotation is named @LogRecordAnnotation. Next, let's look at the definition of the next annotation:

@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 "";
}

In addition to the parameters mentioned above, the annotations also add parameters such as fail, category, detail, and condition. These parameters are to meet specific scenarios. Specific examples will be given later.

parameter name	describe	Is it required
success	Text template for operation log	Yes
fail	Text version of operation log failure	no
operator	Executor of the operation log	no
bizNo	The ID of the business object bound to the operation log	Yes
category	Types of operation logs	no
detail	Extended parameters, record the modification details of the operation log	no
condition	Conditions for logging	no

To keep things simple, there are only two required parameters for the component. Most of the AOP logic in the business is implemented using @Aspect annotations, but the compatibility of annotation-based AOP in Spring boot 1.5 is problematic. In order to be compatible with Spring boot 1.5, we manually implement Spring's AOP logic.

The cut surface is selected by AbstractBeanFactoryPointcutAdvisor , and the cut point is achieved by StaticMethodMatcherPointcut matching the annotation LogRecordAnnotation The enhanced logic of the operation log is realized by implementing the MethodInterceptor

The following is the pointcut logic of the interceptor:

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;
    }
}

The main code of the enhanced logic of the aspect is as follows:

@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;
}

The flow of the interception logic:

It can be seen that the record persistence of the operation log is executed after the method is executed. When the method throws an exception, the exception will be caught first, and then the exception will be thrown after the operation log persistence is completed. Before the execution of the business method, the pre-parsed custom function is evaluated, which solves the aforementioned need to query and modify the content before modification.

4.2.2 Analysis logic

template analysis

Spring 3 provides a very powerful feature: Spring EL, SpEL is used as the core basic module of expression evaluation in Spring products, and it can be used independently from Spring. for example:

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));
}

This method will print "Zhang San". The class diagram parsed by LogRecord is as follows:

Parsing core class : LogRecordValueParser encapsulates custom functions and LogRecordExpressionEvaluator parsing class 0614831821fd24.

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 inherits from the CachedExpressionEvaluator class. There are two Maps in this class, one is expressionCache and the other is targetMethodCache. As you can see in the above example, SpEL will be parsed into an Expression expression, and then get the corresponding value according to the passed in Object, so the expressionCache is to cache the corresponding relationship between the method, the expression and the SpEL Expression, and let the method annotate The SpEL expression added above is only parsed once. The following targetMethodCache is used to cache the Object passed into the Expression expression. The core parsing logic is the last line of code above.

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

getExpression method will get the parsed Expression instance of the expression on the @LogRecordAnnotation annotation from the expressionCache, and then call the getValue method, and the getValue pass in an evalContext which is similar to the order object in the above example. The implementation of Context will be introduced below.

log context implementation

The following example puts the variables in the LogRecordContext, and then the SpEL expression can smoothly parse the parameters that do not exist in the method. From the SpEL example above, it can be seen that the parameters of the method and the variables in the LogRecordContext should be put in getValue in the Object of SpEL's 0614831821fdad method can the value of the expression be parsed smoothly. Let's see how to achieve:

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

An EvaluationContext is created in LogRecordValueParser to parse method parameters and variables in Context for SpEL. The relevant code is as follows:

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

When parsing, getValue method is the above EvaluationContext object. The following is the inheritance system of the LogRecordEvaluationContext object:

LogRecordEvaluationContext does three things:

• Put the parameters of the method in the RootObject parsed by SpEL.
• Put all the variables in LogRecordContext into RootObject.
• Put the return value of the method and ErrorMsg in RootObject.

The code of LogRecordEvaluationContext is as follows:

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);
    }
}

The following is the implementation of LogRecordContext. This class maintains a stack through a ThreadLocal variable. Inside the stack is a Map, which corresponds to the name and value of the variable.

public class LogRecordContext {

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

InheritableThreadLocal is used above, so there will be problems when using LogRecordContext in the thread pool scenario. If you support the thread pool, you can use Alibaba's open source TTL framework. Then why not directly set a ThreadLocal<Map<String, Object>> object, but set a Stack structure? Let's take a look at the reasons for this.

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

The execution flow of the above code is as follows:

There seems to be no problem, but when another method using LogRecordAnnotation is nested inside the method using LogRecordAnnotation, the flow becomes the following form:

It can be seen that after method two executes the release of variables, the logRecord logic of method one continues to be executed. At this time, the Map of ThreadLocal<Map<String, Object>> has been released when parsing, so the corresponding method cannot be obtained in method one. Variables too. Method 1 and Method 2 share the same variable Map. Another problem is that if Method 2 sets the same variable as Method 1, the variables of the two methods will be overwritten with each other. So in the end, the life cycle of the LogRecordContext variable needs to be in the following form:

LogRecordContext will push a Map on the stack every time a method is executed. After the method is executed, the Map will be popped to avoid variable sharing and overwriting problems.

Default operator logic

IOperatorGetService interface in LogRecordInterceptor, this interface can get the current user. The following is the definition of the interface:

public interface IOperatorGetService {

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

The following is an example of obtaining users from the user context:

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"));
        
    }
}

When the component parses the operator, it judges whether the operator in the annotation is empty. If it is not specified in the annotation, we get it from the getUser method of IOperatorGetService. If none is available, an error will be reported.

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);
}

custom function logic

The class diagram of the custom function is as follows:

The following is the interface definition of executeBefore function represents whether the custom function is parsed before the execution of the business code, and the query mentioned above is modified before the content.

public interface IParseFunction {

  default boolean executeBefore(){
    return false;
  }

  String functionName();

  String apply(String value);
}

The code of ParseFunctionFactory is relatively simple, and its function is to inject all IParseFunctions into the function factory.

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();
  }
}

The logic of DefaultFunctionServiceImpl is to find the corresponding IParseFunction according to the passed function name functionName, and then pass the parameters to the apply method of IParseFunction and finally return the value of the function.

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 Log persistence logic

ILogRecordService is also referenced in the code of LogRecordInterceptor. This Service mainly contains the interface for logging.

public interface ILogRecordService {
    /**
     * 保存 log
     *
     * @param logRecord 日志实体
     */
    void record(LogRecord logRecord);

}

The business can implement this save interface, and then save the log on any storage medium. Here is an example of saving in the log file through log.info introduced in section 2.2. The business can set the saving to be asynchronous or synchronous, and it can be placed in a transaction with the business to ensure the consistency of the operation log and the business, or it can be new Open up a transaction to ensure that log errors do not affect business transactions. Businesses can be stored in Elasticsearch, databases or files, and users can implement corresponding query logic according to the log structure and log storage.

@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 logic package

The above logic code has been introduced, then these components need to be assembled and then used by users. When using this component, you only need to add an annotation @EnableLogRecord(tenant = "com.mzt.test") on the entrance of Springboot. Tenant stands for tenant and is used for multi-tenancy.

@SpringBootApplication(exclude = DataSourceAutoConfiguration.class)
@EnableTransactionManagement
@EnableLogRecord(tenant = "com.mzt.test")
public class Main {

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

Look at EnableLogRecord code, the code Import LogRecordConfigureSelector.class , in LogRecordConfigureSelector exposed class LogRecordProxyAutoConfiguration class.

@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Import(LogRecordConfigureSelector.class)
public @interface EnableLogRecord {

    String tenant();
    
    AdviceMode mode() default AdviceMode.PROXY;
}

LogRecordProxyAutoConfiguration is the core class for assembling the above components, the code is as follows:

@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");
    }
  }
}

This class inherits ImportAware to get tenant attributes on EnableLogRecord. This class uses variables logRecordAdvisor and logRecordInterceptor to assemble AOP, and at the same time injects custom functions into logRecordAdvisor.

External extension class : IOperatorGetService , ILogRecordService , IParseFunction . The business can implement the corresponding interface by itself. Because @ConditionalOnMissingBean is configured, the user's implementation class will override the default implementation in the component.

5. Summary

This article introduces the common writing methods of the operation log, and how to make the realization of the operation log simpler and easier to understand; through the four modules of the component, the specific implementation of the component is introduced. Regarding the above component introduction, if you have any questions, please leave a message at the end of the article, and we will answer them.

6. About the author

Zhantong, joined Meituan in 2020, engineer of basic R&D platform/R&D quality and efficiency department.

7. References

• Canal
• spring-framework
• Spring Expression Language (SpEL)
• difference between ThreadLocal, InheritableThreadLocal, and TransmittableThreadLocal

8. Recruitment Information

The R&D Quality and Efficiency Department of Meituan is committed to building a first-class continuous delivery platform in the industry. It is now recruiting engineers related to basic components, coordinated in Beijing/Shanghai. Interested students are welcome to join. Resume can be sent to: [e-mail] (please indicate the subject of the email: Meituan R&D Quality and Efficiency Department).

Read more technical articles from the

front end | algorithm | backend | data | security | operation and maintenance | iOS | Android | test

16148318220395 | . You can view the collection of technical articles from the Meituan technical team over the years.

| This article is produced by the Meituan technical team, and the copyright belongs to Meituan. Welcome to reprint or use the content of this article for non-commercial purposes such as sharing and communication, please indicate "the content is reproduced from the Meituan technical team". This article may not be reproduced or used commercially without permission. For any commercial activity, please send an email to [e-mail] to apply for authorization.