服务端接口日志打印的几种方法
一个服务上线对外提供服务时，接口日志打印是现网运维一个必不可缺的部分。今天这篇文章，主要讲解一个SpringWeb服务，统一处理接口日志打印的方法。
接口日志主要包含的字段包括如下几点：接口路径，接口请求时间，接口入参，接口出参。且需要针对性的对接口出入参进行数据脱敏处理。
使用AOP打印接口日志
接口日志切面选择
对于比较简单可，可以直接拦截所有的http请求，并打印所有的request.parameters。但这样不够灵活，容易将文件数据或敏感数据打印。这里，通过自定义接口日志注解的方式作为切点。
注解定义
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface InterfaceLog {
}
编写aop切面
@Aspect
@Component
public class InterfaceLogAspect {
private static final Logger INTERFACE_LOG = LogUtil.getInterfaceLogger();
@Pointcut("@annotation(xxx.xxx.xxx.annotation.InterfaceLog) ")
public void log() {
}
@Before("log()")
public void init(JoinPoint joinPoint) throws CException {
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
// ......
}
@AfterReturning(returning = "rsp", pointcut = "log()")
public void doAfterReturning(JoinPoint jp, Object rsp) throws CException {
printNormalInterfaceLog(rsp);
}
@AfterThrowing(throwing = "ex", pointcut = "log()")
public void ajaxThrow(JoinPoint jp, Exception ex) throws CException {
printErrorInterfaceLog(ex);
}
}
网络接口请求中的数据共享传递方案
1、ThreadLocal方案
构造定义ThreadLocal对象
public final class SystemContext {
private static final ThreadLocal<LogInfo> LOG_CONTEXT = new ThreadLocal<LogInfo>();
private SystemContext() {}
public static LogInfo getLogInfo() {
return LOG_CONTEXT.get();
}
public static void setLogInfo(LogInfo logInfo) {
LOG_CONTEXT.set(logInfo);
}
}
ThreadLocal对象使用场景
在before时将startTime设定，在afterReturn里打印日志时可以取出startTime以计算
@Before("log()")
public void init(JoinPoint joinPoint) throws CException {
// LogInfo logInfo = new LogInfo (System.currentTimeMillis(),"other paramter");
SystemContext.setLogInfo(logInfo);
}
private void printNormalInterfaceLog(Object rsp) {
LogInfo logInfo = SystemContext.getLogInfo();
logInfo.setCostTime(System.currentTimeMillis() - logInfo.getStartTime());
logInfo.setRsp(LogUtil.toLogString(rsp));
INTERFACE_LOG.info(logInfo.toLogString());
}
2、切片方法参数匹配
切片方法中，匹配一个context对象，(其作用和ThreadLocal对象类似，都可以在切片和方法中传递数据)，对该对象进行数据的读写操作。
@Before("log() && args(context,..)")
public void init(JoinPoint joinPoint, Context context) throws CException {
context.setStartTime(System.currentTimeMillis());
}
@AfterReturning(returning = "rsp", pointcut = "log() && args(context,..)")
public void doAfterReturning(JoinPoint jp, Object rsp, Context context) throws CException {
printNormalInterfaceLog(context, rsp);
}
@AfterThrowing(throwing = "ex", pointcut = "log()&& args(context,..)")
public void ajaxThrowss(JoinPoint jp, Exception ex, Context context) throws CException {
printErrorInterfaceLog(context, ex);
}
对应的接口也需要传入该参数, 也可是使用context对象里的其他加工好的数据。
@RequestMapping(value = "/getUserInfo", method = RequestMethod.POST)
@InterfaceLog
@ResponseBody
public GetUserInfoRsp getUserInfo(Context context) throws CException {
LOG.debug("come into getUserInfo");
GetUserInfoRsp rsp = loginService.getUserInfo(context);
return rsp;
}
在切面中获取接口信息
接口路径：可以通过HttpServletRequest对象获取到；
接口请求时间：可以通过上诉的数据传递方案，从threadLocal或切片参数中获取时间差；
接口出参：可以通过AfterReturn方法内的返回值直接获取到；
接口入参：可以通过上诉的数据传递方案，从threadLocal或切片参数中获取，也可以从JoinPoint参数中提取。
private Optional<Object> getRequestBodyParam(JoinPoint joinPoint){
if (joinPoint instanceof MethodInvocationProceedingJoinPoint) {
Signature signature = joinPoint.getSignature();
if (signature instanceof MethodSignature) {
MethodSignature methodSignature = (MethodSignature) signature;
Method method = methodSignature.getMethod();
Parameter[] methodParameters = method.getParameters();
if (null != methodParameters
&& Arrays.stream(methodParameters).anyMatch(p-> AnnotationUtils.findAnnotation(p, RequestBody.class) != null)) {
return Optional.of(joinPoint.getArgs());
}
}
}
return Optional.empty();
}
作者：crick77
链接：https://ld246.com/article/1541226397969
来源：链滴
协议：CC BY-SA 4.0 https://creativecommons.org/licenses/by-sa/4.0/
Filter中打印接口日志
背景，在使用公司的微服务框架时开发web服务时，发现通过aop打印日志有诸多限制。无法在aop中获取ServletRequestAttributes对象；接口仅能接收一个入参对象，无法通过切片参数的方式传递数据。然后研究了Filter中打印接口日志的一些姿势。
实现HttpServerFilter
通过HttpServerFilter的方式，在afterReceiveRequest中获取startTime,uri,reqBody数据，在beforeSendResponse中获取rspBody、costTime。
public class InterfaceLogFilter implements HttpServerFilter {
@Override
public Response afterReceiveRequest(Invocation invocation, HttpServletRequestEx httpServletRequestEx) {
long startTime = Instant.now().toEpochMilli();
Object reqBody = FilterHelper.getReqBody(invocation);
LogInfo logInfo =
new LogInfo(
MDCUtil.getTranId(),
httpServletRequestEx.getPathInfo(),
startTime,
ToStringUtil.logString(reqBody));
SystemContext.setLogInfo(logInfo);
return null;
}
@Override
public void beforeSendResponse(Invocation invocation, HttpServletResponseEx responseEx) {
byte[] plainBodyBytes = responseEx.getBodyBytes();
Object rspBody = FilterHelper.getRspBody(invocation, plainBodyBytes);
logInfo.setRsp(ToStringUtil.logString(rspBody));
logInfo.setCostTime(Instant.now().toEpochMilli() - logInfo.getStartTime());
LOGGER.info(logInfo.toLogString());
}
}
从Invocation对象中提取出接口入参和出参对象
这其中的难点在于如何从Invocation对象中提取出接口入参和出参对象
下面给出简单的实现说明。
获取接口入参，可以通过微服务的Swagger能力，获取到paramters，直接从invocation.getSwaggerArgument(index)中获取到入参对象
获取接口出参，同理从invocation中获取到returnType，然后反序列化出出参对象。
public static Object getReqBody(Invocation invocation) {
OperationMeta meta = invocation.getOperationMeta();
List<Parameter> params = meta.getSwaggerOperation().getParameters();
if (bodyMetaCache.get(meta.getSchemaQualifiedName()) != null) {
return invocation.getSwaggerArgument(bodyMetaCache.get(meta.getSchemaQualifiedName()));
}
int index = -1;
for (int i = 0; i < params.size(); ++i) {
String in = ((Parameter) params.get(i)).getIn();
if (in.equalsIgnoreCase(LOCATION_BODY)) {
index = i;
bodyMetaCache.put(meta.getSchemaQualifiedName(), i);
break;
}
}
if (index < 0) {
return null;
}
return invocation.getSwaggerArgument(index);
}
public static Object getRspBody(Invocation invocation, byte[] plainBodyBytes) {
Class<?> returnType = invocation.getOperationMeta().getMethod().getReturnType();
Object requestBody = null;
String bodyString = new String(plainBodyBytes, StandardCharsets.UTF_8);
try {
requestBody = OBJECT_MAPPER.readValue(bodyString, returnType);
} catch (Exception e) {
log.error("RspBody parse error");
}
return requestBody;
}
通过一个统一的接口接收处理所有的请求
方案基本实现
如下，开放一个统一的对外的RestController,设定@RequestMapping(path = "/{path:.*}")通配所有接口请求，业务逻辑处理前后做接口日志打印。
/**
* 面向端侧开放的restful风格接口
*
*/
@RestController
@Slf4j
@RequestMapping(path = "/prefix/path")
public class AppController extends BaseController {
@PostMapping(path = "/{path:.*}", produces = MediaType.APPLICATION_JSON_VALUE,
consumes = MediaType.APPLICATION_JSON_VALUE)
public BaseResponse appApi(HttpServletRequest servletRequest) {
long begin = System.currentTimeMillis();
BaseResponse response = null;
ServiceHandledEvent.Builder builder = new ServiceHandledEvent.Builder(this);
try {
// 获取接口请求入参
String requestBody = getRequestBody(servletRequest);
BaseRequest request = parseBaseRequest(requestBody);
String commandName = getCommandName(servletRequest);
//业务逻辑处理在processCommond中进行
response = processCommand(commandName, request);
} catch (Exception e) {
response = new BaseResponse();
} finally {
// 打印接口日志
long end = System.currentTimeMillis();
builder.responseTime(end - begin) // 记录接口请求时间
.requestData(ToStringUtil.logString(request)) // 记录脱敏后的入参
.responseData(ToStringUtil.logString(response)) // 记录脱敏后的出参
.url(servletRequest.getPathInfo()); //记录接口路径
// 继续记录servletRequest的详细数据或出参的含义，以便于现网大数据监控运维
ServiceHandledEvent event = builder.build();
eventPushService.pushEvent(event);
// 通过EventPushService的方式让日志记录解耦
}
return response;
}
}
方案简析
这种方案，对外暴露的只有一个通配的RequestMapping，对于接口的可维护性要差一点。
具体表现在：无法自动生成swagger文件，需要手动维护接口的出入参信息，这在联合开发的情况下不利于管理；如果作为一个微服务，注册中心无法探测到其接口的变动，不便于监控。
但它的优点在于：将以往项目众多aop、filter或interceptor内的逻辑，都可以挪到RestController内进行处理。代码错误更好定位，业务流程也跟清晰。
后记
方案不是一成不变的，filter方案打印接口日志里的套路，也可以用在aop中。提取接口出参对象、数据共享传递，也可以根据具体情况用在其他场景。不同方案中的技术手段可以交错着用，具体需要看技术框架及业务场景的限制及要求。
这篇文章里分享的接口日志打印方案，相对于网上其他的方案，可能会显得繁琐。其主要原因在于所涉及的业务对接口信息要求更复杂，且对出入参有数据脱敏的要求。仅仅获取接口出入参的字符串时不够的。不然的话，索性在网关中记录所有接口也是可行的
至于日志内数据脱敏，在其他文章中会进一步分析讲解。
