1.Background
In the process of daily troubleshooting, we know that incorrect input parameters are one of the common reasons for interface call failure. Especially the callback interface and openAPI interface provided for third-party calls. Since the level of third-party developers cannot be guaranteed, problems often arise. I repeatedly come to you to ask why it doesn’t work, and even complain about it. “What kind of interface?” At this time, you must be confused and angry, and want to start a blame game, but the other party may be the father of Party A’s financier, and you don’t have the evidence to prove that it is the other party’s call at the first time. For questions, you can only bear to ask him how to adjust the interface, and humbly ask him to send the parameters to take a look. . . In order to reverse the situation, I straightened my back and said: Can you be more reliable? Today we will talk about how to elegantly implement unified printing interface API parameter logs in system services, so that server-side development can quickly dump the blame and provide evidence! ! !
Of course, it should be noted that printing too many logs will have a certain impact on performance, and if you use ELK architecture to collect distributed system logs, it will also increase the pressure of log collection and synchronization, and even cause high delays. . Therefore, when we print logs to score the importance of environment and interfaces, we generally only need to enable them in the test environment. In this way, when third-party joint debugging, the joint debugging must be passed in the test environment first, and finally the interfaces of the online environment can be officially adjusted. Of course, some interfaces are very important. , the troubleshooting credentials also need to be retained online. At this time, the online interface parameter log also needs to be printed. This requires us to:The environment and interface for printing parameter logs can be configured and specified, and the main focus is dynamic flexibility.
Without further ado, let’s take a look at how we implement this functional requirement
2. Implementation
When it comes to unified implementation, aspect processing definitely comes to mind. Aspect-oriented programming is a programming paradigm that serves as a supplement to OOP object-oriented programming and is used to handle cross-cutting concerns distributed in various modules in the system, such as Transaction Management, Permissions Control, Cache Control, Log Printing and more. Before talking about aspect implementation and printing logs, let’s first take a look at how to achieve dynamic and flexible configurability?
2.1 Control whether the environment prints interface parameter logs
This is relatively simple to implement. We only need to set a switch in the configuration file to enable printing of interface parameter logs:
@Data
@ConfigurationProperties(prefix = "ptc.apiLog")
public class ApiLogProperties {<!-- -->
/**
* Whether to enable interface log printing, default
*/
private Boolean enable = Boolean.FALSE;
}
The default here is false, which means not to enable interface parameter log printing, and then use it in the automatic configuration class:
@Configuration
@EnableConfigurationProperties({<!-- -->ApiLogProperties.class})
@PropertySource("classpath:/web-default.properties")
public class PlasticeneWebAutoConfiguration {<!-- -->
/**
* Inject api log printing interceptor
* @return
*/
@Bean
// @ConditionalOnProperty(name = "ptc.apiLog.enable", havingValue = "true")
public ApiLogPrintAspect apiLogPrintAspect() {<!-- -->
return new ApiLogPrintAspect();
}
}
Note that ApiLogPrintAspect is injected here and does not use conditional assembly. The conditional assembly code has been commented out. The reason for this is that we perform switch judgment in the aspect class below, so that the switch interface can be updated with the help of dynamic configuration. When parameters are printed, there is no need to restart the service. In fact, the above attribute configuration class is not necessarily needed, because we can also directly inject the value according to ptc.api.log.enable. The attribute configuration class is generally for one function point. It is only suitable for multiple configurations. I wrote it here to implement automatic prompts for custom configurations in the Spring Boot business system:
If you are unclear about how to implement automatic prompts for custom configurations in the Spring Boot business system, you can consult the information on your own.
2.2 Control whether the interface prints parameter logs
This kind of dynamic configuration that needs to specify whether an interface needs to print parameter logs needs to be implemented with the help of annotations:
@Retention(RetentionPolicy.RUNTIME)
@Target({<!-- -->ElementType.TYPE, ElementType.METHOD})
@Documented
public @interface ApiLog {<!-- -->
}
This annotation definition is very simple, it doesn’t even have attributes, because it only needs to be marked on the interface method or the class where it is located. The annotation can be applied to the class or the interface method. When it is applied to the class, it means that all methods under the class are You need to print the interface parameter log.
Project Recommendation: Based on the underlying framework encapsulation of SpringBoot2. Unified management of the framework. The idea of componentization is introduced to achieve high cohesion, low coupling, high configurability, and pluggability. Strictly control package dependencies and unified version management to minimize dependencies. Focus on code specifications and comments, very suitable for personal learning and corporate use
Github address: https://github.com/plasticene/plasticene-boot-starter-parent
Gitee address: https://gitee.com/plasticene3/plasticene-boot-starter-parent
WeChat public account: Shepherd advanced notes
Communication and discussion qun: Shepherd_126
2.3 AOP aspect to implement log printing
AOP aspects are used here to use this function. Of course, filters can also be used to achieve the effect of log aspects. However, when using filters, be careful when obtaining input parameters and read the request data stream through request.getInputStream (or getReader). (It can parse out data whose content-Type is application/x-www-form-urlencoded, application/json, and text/xml (note: multipart/form-data does not work), but!!! in the subsequent controller The data stream cannot be obtained in the interface. The main reason is that the binary stream (character stream) cannot be read once in the filter and once in another Servlet, that is, after an InputSteam (BufferedReader) object is read, It will not be read again. We have analyzed this in the previous summary. For details, see: How Spring Boot implements interface parameter encryption and decryption. Back to the topic and look at the aspect logic:
@Aspect
@Slf4j
@Order(value = OrderConstant.AOP_API_LOG)
public class ApiLogPrintAspect {<!-- -->
@Resource
private ApiLogProperties apiLogProperties;
/**
* Declare pointcut
*
* @param joinPoint entry point
*Expression example:
* Execution of any public method: execution(public * *(..))
* Execution of any method starting with "set": execution(* set*(..))
* Execution of any method of the AccountService interface: execution(* com.xyz.service.AccountService.*(..))
* Execution of any method defined in the service package: execution(* com.xyz.service.*.*(..))
* Execution of any method of any class defined in the service package and all sub-packages: execution(* com.xyz.service..*.*(..))
* @return return value
* @throws Throwable exception
*/
@Around("execution(* com.plasticene..controller..*(..))")
public Object timeAround(ProceedingJoinPoint joinPoint) throws Throwable {<!-- -->
// The switch judgment is done here instead of injecting the aspect bean based on the switch condition, because it is to facilitate the modification of the configuration switch dynamic update to control the switch printing interface parameter log
if (!apiLogProperties.getEnable()) {<!-- -->
return joinPoint.proceed();
}
ApiLog apiLog = getApiLog(joinPoint);
if (Objects.isNull(apiLog)) {<!-- -->
return joinPoint.proceed();
}
long start = System.currentTimeMillis();
HttpServletRequest request = getRequest();
RequestInfo requestInfo = new RequestInfo();
requestInfo.setIp(request.getRemoteAddr());
requestInfo.setUrl(request.getRequestURL().toString());
requestInfo.setHttpMethod(request.getMethod());
requestInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName()));
requestInfo.setRequestParams(getRequestParams(joinPoint, request));
log.info("Request Info : {}", JsonUtils.toJsonString(requestInfo));
Object result = joinPoint.proceed();
log.info("Response result: {}", JsonUtils.toJsonString(result));
log.info("time cost: {}", System.currentTimeMillis() - start);
return result;
}
private Object getRequestParams(ProceedingJoinPoint joinPoint, HttpServletRequest request) throws UnsupportedEncodingException {<!-- -->
Object[] args = joinPoint.getArgs();
Object params = null;
String queryString = request.getQueryString();
String method = request.getMethod();
if (args.length > 0) {<!-- -->
// There is an interface type of body. At this time, HttpServletRequest request and HttpServletResponse response must be excluded as interface method parameters.
if ("POST".equals(method) || "PUT".equals(method) || "DELETE".equals(method)) {<!-- -->
int length = args.length;
int index = 0;
Object object = null;
while (index < length) {<!-- -->
Object o = args[index];
index + + ;
if (o instanceof HttpServletRequest || o instanceof HttpServletResponse) {<!-- -->
continue;
} else {<!-- -->
object = o;
break;
}
}
if (object instanceof MultipartFile) {<!-- -->
MultipartFile multipartFile = (MultipartFile) object;
params = MessageFormat.format("File name: {0}, Size: {1}", multipartFile.getOriginalFilename(), multipartFile.getSize());
} else {<!-- -->
params = object;
}
// When the method is get and the interface parameter is a path parameter, then queryString is null at this time
} else if ("GET".equals(method) & amp; & amp; StrUtil.isNotBlank(queryString)) {<!-- -->
params = URLDecoder.decode(queryString, "utf-8");
}
}
return params;
}
private HttpServletRequest getRequest() {<!-- -->
ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = requestAttributes.getRequest();
return request;
}
private ApiLog getApiLog(JoinPoint joinPoint) {<!-- -->
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
Method method = methodSignature.getMethod();
ApiLog apiLog = method.getAnnotation(ApiLog.class);
if (Objects.isNull(apiLog)) {<!-- -->
apiLog = method.getDeclaringClass().getAnnotation(ApiLog.class);
}
return apiLog;
}
}
It can be seen that we have made certain parsing and adaptation of the interface input parameters. The AOP entry point execution(* com.plasticene..controller..*(..)) must satisfy this package path. Execute aspect logic, which conforms to a company’s project service structure specifications. Using the same prefix as the package name facilitates subsequent unified interception logic processing, and then determines the log switch and whether it is marked with @ApiLog. Finally, the interface request parameters and response parameters are logged. The log printing here is only printed in one line, and there is no format. This can effectively reduce the amount of logs, because we usually check the logs based on traceIdTo query the parameter printing of a request, directly copy it and find an online JSON parsing tool to clearly see the log information. At the same time, @Order(value = OrderConstant.AOP_API_LOG) is used here to control the execution order of aspect components, and the priority is specified through the @Order(i) annotation. Note: The smaller the value of i, the higher the priority.
2.4 Usage examples
Turn on the print log switch in the configuration file of the business project service
ptc:
api:
log:
enable: true
Write test interface:
@PostMapping("/test/api/log")
@ApiLog
public User printApiLog(@RequestBody User user) throws InterruptedException {<!-- -->
log.info("api log printed....");
TimeUnit.SECONDS.sleep(1);
return user;
}
Interface call:
The console log prints as follows:
[1719387065344552960] [INFO] [2023-11-01 00:13:16.007] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Request Info: {"ip":"127.0.0.1","url":"http://127.0.0.1:18888/fds/test/test/api/log","httpMethod":"POST","classMethod" :"com.plasticene.fast.controller.TestController.printApiLog","requestParams":{"createTime":null,"updateTime":null,"creator":null,"updater":null,"id":123, "username":null,"password":null,"name":"she haha","mobile":"1234556457","gender":1,"status":null,"email":"shepherd@163. com","remark":"Test printing api log"}}
[1719387065344552960] [INFO] [2023-11-01 00:13:16.073] [http-nio-18888-exec-1@29351] com.plasticene.fast.controller.TestController printApiLog$original$kjC7ivXx: api log printed ....
[1719387065344552960] [INFO] [2023-11-01 00:13:17.087] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Response result: { "createTime":null,"updateTime":null,"creator":null,"updater":null,"id":123,"username":null,"password":null,"name":"she haha" ,"mobile":"1234556457","gender":1,"status":null,"email":"[email protected]","remark":"Test printing api log"}
[1719387065344552960] [INFO] [2023-11-01 00:13:17.090] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : time cost: 1115
You can see that both the input and output parameters of the interface are printed in detail, but it is found that the interface parameter log and the business log are coupled together, making it difficult to distinguish. So we thought about printing the interface parameter log separately into a log file for easy query. In fact, you only need to specify a topic for the above aspect class @Slf4j
@Slf4j(topic = "ptc.api.log")
Then configure the associated part in the log configuration file:
<!-- 2.5 interface interface log, time rolling output -->
<appender name="INTERFACE_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- The path and file name of the log file being recorded -->
<file>${log.path}/app-interface.log</file>
<!--Log document output format-->
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>UTF-8</charset> <!-- Set the character set here -->
</encoder>
<!-- The rolling strategy of the logger, recording by date, by size -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${log.path}/app-interface-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--Number of days to retain log files-->
<maxHistory>15</maxHistory>
</rollingPolicy>
<!-- This log document only records info level -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>info</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<logger name="ptc.api.log" level="info" additivity="false">
<Appender-ref ref="CONSOLE"/>
<appender-ref ref="INTERFACE_FILE"/>
</logger>
If you need the complete logback.xml log file, please leave a message. I will send it privately. Due to space issues, I will not show it all here.
Execute the above test interface example again. The log files are collected as follows: The logs printed by the interface parameters are collected separately in the app-interface file.
The log printed in our interface logic is output to app-info:
3. Summary
All of the above is our analysis and summary of the functional implementation plan for printing interface parameter logs. Properly printing out logs can help improve the efficiency of troubleshooting, but you cannot print logs at will, which will have a certain impact on interface performance and synchronization with distributed log collection. Delay etc. At the same time, we also analyze how to achieve dynamic flexibility and make it pluggable, and finally classify and archive the logs for easy query.
Finally, the code path of the aspect is attached: https://github.com/plasticene/plasticene-boot-starter-parent/blob/main/plasticene-boot-starter-web/src/main/java/com/plasticene/boot/ web/core/aop/ApiLogPrintAspect.java