Log打印和追踪
前言
Github:https://github.com/HealerJean
一、日志格式
1)log4j
%d{yyyy-MM-dd HH:mm:ss} %-5level -[%-32X{REQ_UID}]- %msg%xEx %logger{36}.%M[%L]%n
2)logback
%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level -[%-32X{REQ_UID}] - %msg -%logger{50}.%M[%L]%n
二、日志打印案例
1、接口调用-需抛异常
@LogIndex
List<SignOutWhiteConfigBatchDto> queryPerson(MerchantSignOutWhiteConfigQueryListReq request) {
ListResponse<SignOutWhiteConfigBatchDto> response;
try {
response = venderSignOutWhiteConfigResource.queryPerson(request);
} catch (Exception e) {
log.error("UserService#queryPerson] ERROR, request:{}, e:{}", JSON.toJSONString(request), ExceptionUtils.getStackTrace(e));
throw new ApiException(ErrorCodeEnum.ERROR_CODE_1011.getCode(), e.getMessage());
}
if (response != null && Boolean.TRUE.equals(response.getSuccess())) {
//log.info("UserService#queryPerson] SUCCESS, request:{}, response:{}", JSON.toJSONString(request), JSON.toJSONString(response));
return response.getValues();
}
log.error("UserService#queryPerson] FAIL, request:{}, response:{}", JSON.toJSONString(request), JSON.toJSONString(response));
throw new ApiDataException(ErrorCodeEnum.ERROR_CODE_1012.getCode(), response == null ? ErrorCodeEnum.ERROR_CODE_1012.getMessage() : response.getMsg());
}
2、接口调用-可兜底
@LogIndex
public List<Person> queryPerson(List<String> userIds) {
try {
UserResponse response = userServiceThrift.queryPerson(userIds);
if (response != null && response.isSuccess() && CollectionUtils.isNotEmpty(response.getList())) {
return res.getList();
}
log.error("[UserService#queryPerson] fail, userIds:{}, signInsuranceInfoQueryRes:{} ",
JsonUtils.toJsonString(res), JsonUtils.toJsonString(response));
} catch (Exception e) {
log.error("[UserService#queryPerson] error, userIds:{}, e:{} ",
JsonUtils.toJsonString(userIds), ExceptionUtils.getStackTrace(e));
}
return null;
}
3、无切面日志-可兜底
public List<Person> queryPerson(List<String> userIds) {
try {
UserResponse response = userServiceThrift.queryPerson(userIds);
if (response != null && response.isSuccess() && CollectionUtils.isNotEmpty(response.getList())) {
log.info("[UserService#queryPerson] success, userIds:{}, signInsuranceInfoQueryRes:{} ",
JsonUtils.toJsonString(res), JsonUtils.toJsonString(response));
return res.getList();
}
log.error("[UserService#queryPerson] fail, userIds:{}, signInsuranceInfoQueryRes:{} ",
JsonUtils.toJsonString(res), JsonUtils.toJsonString(response));
} catch (Exception e) {
log.error("[UserService#queryPerson] error, userIds:{}, e:{} ",
JsonUtils.toJsonString(userIds), ExceptionUtils.getStackTrace(e));
}
return null;
}
三、工具:切面打印接口出入参
1、LogAspect
1)LogIndex
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
public @interface LogIndex {
/**
* 是否打印入参日志,默认是
*/
boolean reqFlag() default true;
/**
* 是否打印出参日志,默认是
*/
boolean resFlag() default true;
}
2)DynamicLogConfiguration
package com.hlj.proj.config;
import lombok.Data;
import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Configuration;
import org.springframework.util.CollectionUtils;
import java.util.HashMap;
import java.util.Map;
@Slf4j
@Data
@Configuration
public class DynamicLogConfiguration {
/**
* 入参是否打印 举例:com.hlj.proj.controller.Log4j2Controller.log4j2
*/
private Map<String, Boolean> reqPrintFlag;
/**
* 出参是否打印 举例:com.hlj.proj.controller.Log4j2Controller.log4j2
*/
private Map<String, Boolean> resPrintFlag;
/**
* getReqPrintFlag
*/
public Map<String, Boolean> getReqPrintFlag() {
if (CollectionUtils.isEmpty(reqPrintFlag)) {
return new HashMap<>(16);
}
return reqPrintFlag;
}
/**
* getResPrintFlag
*/
public Map<String, Boolean> getResPrintFlag() {
if (CollectionUtils.isEmpty(resPrintFlag)) {
return new HashMap<>(16);
}
return resPrintFlag;
}
}
3)LogAspect
package com.hlj.proj.aspect;
import com.hlj.proj.config.DynamicLogConfiguration;
import com.hlj.proj.utils.JsonUtils;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.exception.ExceptionUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import javax.annotation.Resource;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.lang.reflect.Method;
import java.lang.reflect.Parameter;
import java.util.*;
/**
* @author zhangyujin
* @date 2021/11/9 5:24 下午
* @desciption 切面日志
*/
@Slf4j
@Component
@Aspect
@Order(2)
public class LogAspect {
/**
* dynamicLogConfiguration
*/
@Resource
private DynamicLogConfiguration dynamicLogConfiguration;
@Around(value = "(execution(* *(..)) && @annotation(logIndex))", argNames = "pjp,logIndex")
public Object printLog(final ProceedingJoinPoint pjp, LogIndex logIndex) throws Throwable {
Object[] args = pjp.getArgs();
Signature sig = pjp.getSignature();
long start = System.currentTimeMillis();
Method method = null;
Object result;
Object reqParams;
Map<String, Object> map = new HashMap<>(8);
try {
String methodName = pjp.getSignature().getName();
String className = sig.getDeclaringTypeName();
if ((sig instanceof MethodSignature)) {
MethodSignature signature = (MethodSignature) sig;
Object target = pjp.getTarget();
method = target.getClass().getMethod(signature.getName(), signature.getParameterTypes());
} else {
log.error("signature is not instanceof MethodSignature!");
}
if (method == null) {
return pjp.proceed();
}
String key = className + "." + methodName;
map.put("method", key);
Boolean reqPrintFlag = dynamicLogConfiguration.getReqPrintFlag().get(key);
if (Objects.nonNull(reqPrintFlag) && Boolean.TRUE.equals(reqPrintFlag)){
reqParams = getRequestParams(args, method.getParameters());
map.put("req", reqParams);
}
if (Objects.isNull(reqPrintFlag) && Boolean.TRUE.equals(logIndex.reqFlag())) {
reqParams = getRequestParams(args, method.getParameters());
map.put("req", reqParams);
}
result = pjp.proceed();
Boolean resPrintFlag = dynamicLogConfiguration.getResPrintFlag().get(key);
if (Objects.nonNull(resPrintFlag) && Boolean.TRUE.equals(resPrintFlag)){
map.put("res", result);
}
if (Objects.isNull(resPrintFlag) && Boolean.TRUE.equals(logIndex.resFlag())) {
map.put("res", result);
}
} finally {
long timeCost = System.currentTimeMillis() - start;
map.put("timeCost", timeCost + "ms");
log.info("LogAspect:{}", JsonUtils.toJsonString(map));
}
return result;
}
/**
* 重构请求参数
*
* @param args 参数
* @param parameters 参数名
* @return 重构后的请求参数
*/
public Object getRequestParams(Object[] args, Parameter[] parameters) {
if (Objects.isNull(args)) {
return null;
}
if (args.length == 1 && !(args[0] instanceof HttpServletRequest) && !(args[0] instanceof HttpServletResponse)) {
return args[0];
}
List<Object> result = new ArrayList<>();
try {
for (int i = 0; i < args.length; i++) {
Object param = args[i];
if (param instanceof HttpServletRequest) {
result.add("HttpServletRequest");
continue;
}
if (param instanceof HttpServletResponse) {
result.add("HttpServletResponse");
continue;
}
Map<Object, Object> map = new HashMap<>(2);
map.put(parameters[i].getName(), param);
result.add(map);
}
} catch (Exception e) {
log.warn("LogAspect getRequestParams error:{}", ExceptionUtils.getStackTrace(e));
}
return result;
}
}
4)TraceIdAspect
@Aspect
@Component
@Slf4j
@Order(1)
public class TraceIdAspect {
private static final String TRACE_ID_NAME = "REQ_UID";
@Around("execution(* com.hlj.proj.controller.*Controller.*(..))")
public Object traceIdSet(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
String traceId = MDC.get(TRACE_ID_NAME);
if (StringUtils.isBlank(traceId)) {
MDC.put(TRACE_ID_NAME, UUID.randomUUID().toString().replace("-", ""));
}
try {
return proceedingJoinPoint.proceed();
} catch (Exception e) {
Signature sig = proceedingJoinPoint.getSignature();
String className = sig.getDeclaringTypeName();
String methodName = proceedingJoinPoint.getSignature().getName();
log.error("[{}.{}] error:{} ", className, methodName, ExceptionUtils.getStackTrace(e));
throw e;
} finally {
MDC.remove(TRACE_ID_NAME);
}
}
}
四、工具:第三方接口调用出入参日志打印
1、Function
1)ThirdInvokeLogAspect
package com.hlj.proj.service;
import com.hlj.proj.utils.JsonUtils;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.exception.ExceptionUtils;
import org.slf4j.Logger;
import org.springframework.boot.logging.LogLevel;
import java.util.HashMap;
import java.util.Map;
import java.util.function.Function;
/**
* InvokeUtils
*
* @author healerjean
* @date 2021/6/23 9:21 下午.
*/
public class InvokeUtils {
/**
* call
*
* @param method method
* @param req req
* @param function function
* @param logger logger
* @return {@link Res}
*/
public static <Req, Res> Res call(String method, Req req, Function<Req, Res> function, Logger logger) {
return call(method, req, function, logger, null);
}
/**
* call
*
* @param methodName methodName
* @param req req
* @param function function
* @param logger logger
* @param level level
* @return {@link Res}
*/
public static <Req, Res> Res call(String methodName, Req req, Function<Req, Res> function, Logger logger, LogLevel level) {
Res res = null;
String stackTrace = null;
long startTime = System.currentTimeMillis();
try {
res = function.apply(req);
level = level != null ? level : LogLevel.INFO;
} catch (Exception throwable) {
stackTrace = ExceptionUtils.getStackTrace(throwable);
level = level != null ? level : LogLevel.ERROR;
} finally {
log(methodName, req, res, stackTrace, startTime, logger, level);
}
return res;
}
/**
* log
*
* @param method method
* @param requestParam requestParam
* @param responseParam responseParam
* @param stackTrace stackTrace
* @param startTime startTime
* @param log log
* @param level level
*/
private static void log(String method, Object requestParam, Object responseParam, String stackTrace, long startTime, Logger log, LogLevel level) {
try {
long timeCost = System.currentTimeMillis() - startTime;
Map<String, Object> map = new HashMap<>();
map.put("method", method);
map.put("requestParams", requestParam);
map.put("responseParams", responseParam);
map.put("timeCost", timeCost + "ms");
if (StringUtils.isNotBlank(stackTrace)) {
map.put("stackTrace", stackTrace);
}
switch (level) {
case DEBUG:
log.debug("InvokeUtils:{}", JsonUtils.toJsonString(map));
break;
case INFO:
log.info("InvokeUtils:{}", JsonUtils.toJsonString(map));
break;
case WARN:
log.warn("InvokeUtils:{}", JsonUtils.toJsonString(map));
break;
case ERROR:
log.error("InvokeUtils:{}", JsonUtils.toJsonString(map));
break;
default:
log.info("InvokeUtils:{}", JsonUtils.toJsonString(map));
break;
}
} catch (Exception e) {
log.error("InvokeUtils {}", ExceptionUtils.getStackTrace(e));
}
}
}
2、验证
@Test
public void test() {
LogCallTestService logCallTestService = new LogCallTestService();
LogCallTestService.RequestDTO requestDTO = new LogCallTestService.RequestDTO();
requestDTO.setName("healerjean");
requestDTO.setAge(1L);
LogCallTestService.ResponseDTO res = InvokeUtils.call("invokeMethod", requestDTO,
logCallTestService::invokeMethod,
log);
res = InvokeUtils.call("invokeMethod", requestDTO, logCallTestService::invokeMethod, log,
LogLevel.DEBUG);
res = InvokeUtils.call("invokeMethod", requestDTO, logCallTestService::invokeMethod, log,
LogLevel.INFO);
res = InvokeUtils.call("invokeMethod", requestDTO, logCallTestService::invokeMethod, log,
LogLevel.WARN);
res = InvokeUtils.call("invokeMethod", requestDTO, logCallTestService::invokeMethod, log,
LogLevel.ERROR);
}
五、日志唯一标识追踪
1、Controller
过滤器 Log4j2ReqUidFilter
package com.healerjean.proj.config.filter;
import org.slf4j.MDC;
import javax.servlet.*;
import java.io.IOException;
import java.util.UUID;
/**
* @author HealerJean
* @ClassName Log4j2Filter
* @date 2020/6/15 20:12.
* @Description
*/
public class Log4j2ReqUidFilter implements Filter {
private static final String REQ_UID = "REQ_UID";
private FilterConfig filterConfig;
@Override
public void init(FilterConfig filterConfig) throws ServletException {
this.filterConfig = filterConfig;
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
MDC.put(REQ_UID, UUID.randomUUID().toString().replace("-", ""));
filterChain.doFilter(servletRequest, servletResponse);
MDC.remove(REQ_UID);
}
@Override
public void destroy() {
this.filterConfig = null;
}
}
@Bean
public FilterRegistrationBean<Log4j2ReqUidFilter> log4j2ReqUidFilter() {
FilterRegistrationBean<Log4j2ReqUidFilter> fitler = new FilterRegistrationBean<>();
fitler.setFilter(new Log4j2ReqUidFilter());
fitler.addUrlPatterns("/*");
fitler.setName("log4j2ReqUidFilter");
fitler.setDispatcherTypes(DispatcherType.REQUEST);
return fitler;
}
2、dubbo
日志追踪
1)服务提供者
a、aop
切面 pom
依赖
<!-- aop 切面 -->
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
b、ServiceLogAspect
接口出入参日志打印
package com.healerjean.proj.config.aspect;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
@Aspect
@Component
@Slf4j
@Order(1)
public class ServiceLogAspect {
@Around("execution(* com.healerjean.proj.service.*Service.*(..))")
public Object handleControllerLog(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
Signature signature = proceedingJoinPoint.getSignature();
String className = signature.getDeclaringTypeName();
String methodName = signature.getName();
Object[] args = proceedingJoinPoint.getArgs();
long start = System.currentTimeMillis();
try {
log.info("请求开始:类名:【{}】,方法名:【{}】, 参数:【{}】", className, methodName, args);
Object result = proceedingJoinPoint.proceed();
long timeCost = System.currentTimeMillis() - start;
log.info("请求结束:类名:【{}】, 方法名:【{}】, 参数:【{}】, 返回值:{}, 耗时:{}ms。", className, methodName, args, result, timeCost);
return result;
} catch (Exception e) {
long timeCost = System.currentTimeMillis() - start;
log.info("请求出错:类名:【{}】,方法名:【{}】, 参数:【{}】, 耗时:【{}】ms。", className, methodName, args, timeCost);
throw e;
}
}
}
c、ProviderRpcTraceFilter
dubbo日志追踪过滤器
package com.healerjean.proj.config.dubbo;
import com.alibaba.dubbo.common.Constants;
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.*;
import com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import java.util.UUID;
@Activate(group = Constants.PROVIDER, order = 1)
public class ProviderRpcTraceFilter extends FutureFilter {
private static final String DUBBO_REQ_UID = "REQ_UID";
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
String reqUid = RpcContext.getContext().getAttachment(DUBBO_REQ_UID);
if (StringUtils.isBlank(reqUid)) {
//传递丢失
reqUid = "CUSTOM:" + UUID.randomUUID().toString().replace("-", "");
}
MDC.put(DUBBO_REQ_UID, reqUid);
RpcContext.getContext().setAttachment(DUBBO_REQ_UID, reqUid);
try {
return invoker.invoke(invocation);
} finally {
MDC.remove(DUBBO_REQ_UID);
}
}
}
d、配置dubbo过滤器
![image-20200616112740541]https://raw.githubusercontent.com/HealerJean/HealerJean.github.io/master/blogImages/image-20200616112740541.png)
com.alibaba.dubbo.rpc.Filter
ProviderRpcTraceFilter=com.healerjean.proj.config.dubbo.ProviderRpcTraceFilter
2)服务消费者
a、aop
切面 pom
依赖
<!-- aop 切面 -->
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
b、ControllerLogAspect
controller
出入参打印
package com.healerjean.proj.config.aspect;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
@Aspect
@Component
@Slf4j
@Order(1)
public class ControllerLogAspect {
@Around("execution(* com.healerjean.proj.controller.*Controller.*(..))")
public Object handleControllerLog(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
Signature signature = proceedingJoinPoint.getSignature();
String className = signature.getDeclaringTypeName();
String methodName = signature.getName();
Object[] args = proceedingJoinPoint.getArgs();
long start = System.currentTimeMillis();
try {
log.info("请求开始:类名:【{}】,方法名:【{}】, 参数:【{}】", className, methodName, args);
Object result = proceedingJoinPoint.proceed();
long timeCost = System.currentTimeMillis() - start;
log.info("请求结束:类名:【{}】, 方法名:【{}】, 参数:【{}】, 返回值:{}, 耗时:{}ms。", className, methodName, args, result, timeCost);
return result;
} catch (Exception e) {
long timeCost = System.currentTimeMillis() - start;
log.info("请求出错:类名:【{}】,方法名:【{}】, 参数:【{}】, 耗时:【{}】ms。", className, methodName, args, timeCost);
throw e;
}
}
}
c、日志追踪过滤器
package com.healerjean.proj.config.filter;
import org.slf4j.MDC;
import javax.servlet.*;
import java.io.IOException;
import java.util.UUID;
/**
* @author HealerJean
* @ClassName Log4j2Filter
* @date 2020/6/15 20:12.
* @Description
*/
public class Log4j2ReqUidFilter implements Filter {
private static final String REQ_UID = "REQ_UID";
private FilterConfig filterConfig;
@Override
public void init(FilterConfig filterConfig) throws ServletException {
this.filterConfig = filterConfig;
}
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
MDC.put(REQ_UID, UUID.randomUUID().toString().replace("-", ""));
filterChain.doFilter(servletRequest, servletResponse);
MDC.remove(REQ_UID);
}
@Override
public void destroy() {
this.filterConfig = null;
}
}
@Configuration
public class InterceptorConfig extends WebMvcConfigurerAdapter {
@Bean
public FilterRegistrationBean log4j2ReqUidFilter() {
FilterRegistrationBean fitler = new FilterRegistrationBean();
fitler.setFilter(new Log4j2ReqUidFilter());
fitler.addUrlPatterns("/*");
fitler.setName("Log4j2ReqUidFilter");
fitler.setDispatcherTypes(DispatcherType.REQUEST);
return fitler;
}
}
d、ConsumerRpcTraceFilter
dubbo日志追踪过滤器
package com.healerjean.proj.config.dubbo;
import com.alibaba.dubbo.common.Constants;
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.*;
import com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import java.util.UUID;
@Activate(group = Constants.CONSUMER, order = 1)
public class ConsumerRpcTraceFilter extends FutureFilter {
private static final String DUBBO_REQ_UID = "REQ_UID";
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext.getContext().setAttachment(DUBBO_REQ_UID, MDC.get(DUBBO_REQ_UID));
return invoker.invoke(invocation);
}
}
e、配置dubbo过滤器
![image-20200616113137513]https://raw.githubusercontent.com/HealerJean/HealerJean.github.io/master/blogImages/image-20200616113137513.png)
com.alibaba.dubbo.rpc.Filter
ConsumerRpcTraceFilter=com.healerjean.proj.config.dubbo.ConsumerRpcTraceFilter