Recently, the project entered the joint commissioning stage. The interface of the service layer needs to interact with the protocol layer, and the protocol layer needs to assemble the input parameter [JSON string] into the JSON string required by the service layer. It is easy to make mistakes during the assembly process. Into and cause the failure of interface debugging problems in alignment error in many times, so they want to write a request log section put into the information a print, at the same time, the protocol layer to invoke the service layer interface name also appeared in several times, by requesting the log section can know whether the upper have initiated calls, convenient pot can also take out the evidence before and after the end
Writing in the front
This article is practical, for the principle of cutting surface will not explain, will simply introduce the knowledge of cutting surface
Section introduces
Section-oriented programming is a programming paradigm that complements OOP object-oriented programming to address cross-cutting concerns that are distributed across modules in a system, such as transaction management, permission control, cache control, log printing, and so on. AOP divides the functional modules of software into two parts: core concerns and crosscutting concerns. The main function of the business process is the core concern, and the non-core function that needs to be extended is the crosscutting concern. AOP’s role is to separate the various concerns in a system, separating core concerns from crosscutting concerns, and using aspects has the following benefits:
- Focus on one concern/crosscutting logic
- You can easily add/remove concerns
- Less intrusive, enhance code readability and maintainability, so when you want to print the request log it is easy to think of the cut side, the control layer code 0 intrusion
Use of sections [Based on notes]
@aspect => declare this class as an annotation class
Pointcut notes:
@pointcut => Define a Pointcut to simplify code
Notice notes:
- @before => Execute code Before pointcut
- @after => Execute the code After the pointcut
- The return value of the pointcut can be encapsulated by executing the code after the pointcut returns
- AfterThrowing => Execute after pointcut throws an exception
- @around => wrap Around, execute code before and after the pointcut
Start writing a request log section
- Use @pointcut to define pointcuts
@Pointcut("execution(* your_package.controller.. * (..) )")
public void requestServer() {
}
Copy the codePointcut defines a Pointcut that, since it is a request log cut, defines methods under all classes in the Controller package. After defining the pointcut, use the requestServer method name directly in the notification annotation
- Use @before to execute Before the pointcut
@Before("requestServer()")
public void doBefore(JoinPoint joinPoint) {
ServletRequestAttributes attributes = (ServletRequestAttributes)
RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
LOGGER.info("===============================Start========================");
LOGGER.info("IP : {}", request.getRemoteAddr());
LOGGER.info("URL : {}", request.getRequestURL().toString());
LOGGER.info("HTTP Method : {}", request.getMethod());
LOGGER.info("Class Method : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
}
Copy the codeBefore entering the Controller method, print out the caller’S IP, request URL, HTTP request type, and method name called
- Use @around to print an entry parameter into the control layer
@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
long start = System.currentTimeMillis();
Object result = proceedingJoinPoint.proceed();
LOGGER.info("Request Params : {}", getRequestParams(proceedingJoinPoint));
LOGGER.info("Result : {}", result);
LOGGER.info("Time Cost : {} ms", System.currentTimeMillis() - start);
return result;
}
Copy the codeInput parameters, results, and elapsed time are printed
GetRquestParams method
private Map<String.Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
Map<String.Object> requestParams = new HashMap<>();
/ / parameter name
String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
/ / parameter values
Object[] paramValues = proceedingJoinPoint.getArgs();
for (int i = 0; i < paramNames.length; i++) {
Object value = paramValues[i];
// If it is a file object
if (value instanceof MultipartFile) {
MultipartFile file = (MultipartFile) value;
value = file.getOriginalFilename(); // Get the file name
}
requestParams.put(paramNames[i], value);
}
return requestParams;
}
Copy the codeParameters passed with @pathVariable and @requestParam annotations cannot be printed with parameter names, so you need to manually concatenate the parameter names and do special processing for the file object, just get the file name
- Execute After the @after method is called
@After("requestServer()")
public void doAfter(JoinPoint joinPoint) {
LOGGER.info("===============================End========================");
}
Copy the codeNo business logic just prints End
- Complete section code
@Component
@Aspect
public class RequestLogAspect {
private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class);
@Pointcut("execution(* your_package.controller.. * (..) )")
public void requestServer() {
}
@Before("requestServer()")
public void doBefore(JoinPoint joinPoint) {
ServletRequestAttributes attributes = (ServletRequestAttributes)
RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
LOGGER.info("===============================Start========================");
LOGGER.info("IP : {}", request.getRemoteAddr());
LOGGER.info("URL : {}", request.getRequestURL().toString());
LOGGER.info("HTTP Method : {}", request.getMethod());
LOGGER.info("Class Method : {}.{}", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName());
}
@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
long start = System.currentTimeMillis();
Object result = proceedingJoinPoint.proceed();
LOGGER.info("Request Params : {}", getRequestParams(proceedingJoinPoint));
LOGGER.info("Result : {}", result);
LOGGER.info("Time Cost : {} ms", System.currentTimeMillis() - start);
return result;
}
@After("requestServer()")
public void doAfter(JoinPoint joinPoint) {
LOGGER.info("===============================End========================");
}
/** * get the input parameter *@param proceedingJoinPoint
*
* @return* * /
private Map<String.Object> getRequestParams(ProceedingJoinPoint proceedingJoinPoint) {
Map<String.Object> requestParams = new HashMap<>();
/ / parameter name
String[] paramNames =
((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
/ / parameter values
Object[] paramValues = proceedingJoinPoint.getArgs();
for (int i = 0; i < paramNames.length; i++) {
Object value = paramValues[i];
// If it is a file object
if (value instanceof MultipartFile) {
MultipartFile file = (MultipartFile) value;
value = file.getOriginalFilename(); // Get the file name
}
requestParams.put(paramNames[i], value);
}
returnrequestParams; }}Copy the codeHigh concurrency request log facets
After writing the code, I was satisfied with it, but I talked to my friends about it because I thought there might be some improvements. emmmm
Sure enough, there are still places to continue to optimize each information to print a line, in high concurrency requests will indeed appear between requests to print the log serial problem, because the number of requests in the test phase is small, there is no serial situation, sure enough, the production environment is the first development force, can encounter more bugs, Write more robust code to solve the log serialization problem by combining multiple lines of print information into one line, so construct an object
- RequestInfo.java
@Data
public class RequestInfo {
private String ip;
private String url;
private String httpMethod;
private String classMethod;
private Object requestParams;
private Object result;
private Long timeCost;
}
Copy the code- Wrap around the notification method body
@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
long start = System.currentTimeMillis();
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
Object result = proceedingJoinPoint.proceed();
RequestInfo requestInfo = new RequestInfo();
requestInfo.setIp(request.getRemoteAddr());
requestInfo.setUrl(request.getRequestURL().toString());
requestInfo.setHttpMethod(request.getMethod());
requestInfo.setClassMethod(String.format("%s.%s", proceedingJoinPoint.getSignature().getDeclaringTypeName(),
proceedingJoinPoint.getSignature().getName()));
requestInfo.setRequestParams(getRequestParamsByProceedingJoinPoint(proceedingJoinPoint));
requestInfo.setResult(result);
requestInfo.setTimeCost(System.currentTimeMillis() - start);
LOGGER.info("Request Info : {}", JSON.toJSONString(requestInfo));
return result;
}
Copy the codeThe reason for serializing the results of a serialized object is that serialization is more intuitive and clear, and the results can be parsed using online parsing tools.
It’s not bad to solve the serialization problem of high concurrency requests while adding the printing of exception request information, using the @afterthrowing annotation to handle the method of throwing exceptions
- RequestErrorInfo.java
@Data
public class RequestErrorInfo {
private String ip;
private String url;
private String httpMethod;
private String classMethod;
private Object requestParams;
private RuntimeException exception;
}
Copy the codeException notification surround
@AfterThrowing(pointcut = "requestServer()", throwing = "e")
public void doAfterThrow(JoinPoint joinPoint, RuntimeException e) {
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
RequestErrorInfo requestErrorInfo = new RequestErrorInfo();
requestErrorInfo.setIp(request.getRemoteAddr());
requestErrorInfo.setUrl(request.getRequestURL().toString());
requestErrorInfo.setHttpMethod(request.getMethod());
requestErrorInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName()));
requestErrorInfo.setRequestParams(getRequestParamsByJoinPoint(joinPoint));
requestErrorInfo.setException(e);
LOGGER.info("Error Request Info : {}", JSON.toJSONString(requestErrorInfo));
}
Copy the codeFor exceptions, the elapsed time is meaningless, so the elapsed time is not counted and the printing of the exception is added
Finally, here is the complete log request section code:
@Component
@Aspect
public class RequestLogAspect {
private final static Logger LOGGER = LoggerFactory.getLogger(RequestLogAspect.class);
@Pointcut("execution(* your_package.controller.. * (..) )")
public void requestServer() {
}
@Around("requestServer()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
long start = System.currentTimeMillis();
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
Object result = proceedingJoinPoint.proceed();
RequestInfo requestInfo = new RequestInfo();
requestInfo.setIp(request.getRemoteAddr());
requestInfo.setUrl(request.getRequestURL().toString());
requestInfo.setHttpMethod(request.getMethod());
requestInfo.setClassMethod(String.format("%s.%s", proceedingJoinPoint.getSignature().getDeclaringTypeName(),
proceedingJoinPoint.getSignature().getName()));
requestInfo.setRequestParams(getRequestParamsByProceedingJoinPoint(proceedingJoinPoint));
requestInfo.setResult(result);
requestInfo.setTimeCost(System.currentTimeMillis() - start);
LOGGER.info("Request Info : {}", JSON.toJSONString(requestInfo));
return result;
}
@AfterThrowing(pointcut = "requestServer()", throwing = "e")
public void doAfterThrow(JoinPoint joinPoint, RuntimeException e) {
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
RequestErrorInfo requestErrorInfo = new RequestErrorInfo();
requestErrorInfo.setIp(request.getRemoteAddr());
requestErrorInfo.setUrl(request.getRequestURL().toString());
requestErrorInfo.setHttpMethod(request.getMethod());
requestErrorInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName()));
requestErrorInfo.setRequestParams(getRequestParamsByJoinPoint(joinPoint));
requestErrorInfo.setException(e);
LOGGER.info("Error Request Info : {}", JSON.toJSONString(requestErrorInfo));
}
/** * get the input parameter *@param proceedingJoinPoint
*
* @return* * /
private Map<String.Object> getRequestParamsByProceedingJoinPoint(ProceedingJoinPoint proceedingJoinPoint) {
/ / parameter name
String[] paramNames = ((MethodSignature)proceedingJoinPoint.getSignature()).getParameterNames();
/ / parameter values
Object[] paramValues = proceedingJoinPoint.getArgs();
return buildRequestParam(paramNames, paramValues);
}
private Map<String.Object> getRequestParamsByJoinPoint(JoinPoint joinPoint) {
/ / parameter name
String[] paramNames = ((MethodSignature)joinPoint.getSignature()).getParameterNames();
/ / parameter values
Object[] paramValues = joinPoint.getArgs();
return buildRequestParam(paramNames, paramValues);
}
private Map<String.Object> buildRequestParam(String[] paramNames, Object[] paramValues) {
Map<String.Object> requestParams = new HashMap<>();
for (int i = 0; i < paramNames.length; i++) {
Object value = paramValues[i];
// If it is a file object
if (value instanceof MultipartFile) {
MultipartFile file = (MultipartFile) value;
value = file.getOriginalFilename(); // Get the file name
}
requestParams.put(paramNames[i], value);
}
return requestParams;
}
@Data
public class RequestInfo {
private String ip;
private String url;
private String httpMethod;
private String classMethod;
private Object requestParams;
private Object result;
private Long timeCost;
}
@Data
public class RequestErrorInfo {
private String ip;
private String url;
private String httpMethod;
private String classMethod;
private Object requestParams;
private RuntimeException exception; }}Copy the codeAdd it to your application quickly [if not], if there is no log, always suspect that the upper level is wrong, but there is no evidence
You can trace the entire invocation chain based on traceId. The following uses log4j2 as an example to describe how to add traceId
- Adding interceptors
public class LogInterceptor implements HandlerInterceptor {
private final static String TRACE_ID = "traceId";
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
String traceId = java.util.UUID.randomUUID().toString().replaceAll("-"."").toUpperCase();
ThreadContext.put("traceId", traceId);
return true;
}
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
throws Exception {
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
throws Exception{ ThreadContext. remove(TRACE_ID); }}Copy the codeAdd traceId through ThreadContext before invocation and remove traceId after invocation
- Modify the log configuration file. Add the traceId placeholders to the original log format
<property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>
Copy the code- perform
DMC is used to configure logback and log4j in much the same way as ThreadContext. Replace threadContext.put with mdC.put and modify the log configuration file.
MDC is under the SLF4J package, and which logging framework it uses depends on our dependencies.
