如何优雅的打印日志？

一、背景

二、日志目录的设置

三、准备工作

1、建表

2、准备Springboot工程

3、日志目录定义

4、ThreadLocalHolder

5、BaseRequest

6、BaseResult：

7、BaseInterceptor

四、开始编码

1、接口层ApiInterceptor

2、持久层DalInterceptor

3、拦截规则

4、logback-spring.xml

五、测试

1、正常测试

2、异常测试

六、git源码

一、背景

一般我们程序里打印日志可以帮助我们排查问题，我们也可以通过日志，来判断接口的成功、耗时等情况，而且按照一定的日志格式来打印的话，还可以用于告警平台，可以计算接口总量、成功量、失败量、失败率、耗时等，通过短信、钉钉等通知到我们。

那么接下来，我们就来看看怎么样才能规范且优雅的打印我们的日志。

二、日志目录的设置

一般我们使用Spring来开发管理后台或者api时，都会遵循一些分层范式， api -> manager -> service -> dao，那么根据这种分层，我们考虑为我们的程序设计以下几种日志目录（假设我们的服务是 maple）：

maple-api-digest.log：接口摘要日志，格式为：[traceId][接口名.方法名,耗时,结果] 用于最直观的看到接口的大致情况maple-api-request-result.log：接口请求响应日志，格式为：
[traceId][接口名#方法名,request:]
[traceId][接口名#方法名,result:]
这里主要是记录我们接口的请求参数和响应结果，帮助排查问题maple-biz-manager.log：manager层日志，这里没有固定的格式，就是我们在程序中用logger.info()打印的具体的日志了maple-biz-service.log：service层日志，这里没有固定的格式，就是我们在程序中用logger.info()打印的具体的日志了maple-dal-digest.log：持久层摘要日志，格式为：[traceId][DAO层名字#方法名,读写类型,耗时,结果条数]common-error.log：把程序里所有的报错，都放进这里。以上都是最基本的日志目录，我们还可以根据不同的场景，增加日志目录，比如：1、有重试任务的话，增加 maple-retry-task.log
2、调其他服务接口的话，增加 maple-client-A服务.log、maple-client-B服务.log
3、有消息中间件的话，增加 maple-biz-event.log
.........

在日志中增加traceId可以有助于我们跟踪接口的整个链路情况，我们这里就使用简单的UUID来做

三、准备工作

1、建表

CREATE TABLE `user` (`user_id` varchar(16) DEFAULT NULL,`user_name` varchar(16) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `user`.`user`(`user_id`, `user_name`) VALUES ('123', 'maple');

2、准备Springboot工程

准备一个Springboot工程，把controller、service、dao、xml都完成，程序运行成功，这里忽略。

3、日志目录定义

package com.maple.monitor.monitor;public class LogNames {public static final String API_DIGEST = "API-DIGEST";public static final String API_REQUEST_RESULT = "API-REQUEST-RESULT";public static final String BIZ_MANAGER = "BIZ-MANAGER";public static final String BIZ_SERVICE = "BIZ-SERVICE";public static final String DAL_DIGEST = "DAL-DIGEST";public static final String COMMON_ERROR = "COMMON-ERROR";
}

4、ThreadLocalHolder

因为我们加入了traceId，考虑使用ThreadLocal，一个请求中的每个地方都能拿到这个traceId，但是不要忘记remove

package com.maple.monitor.monitor.context;public class ThreadLocalHolder {private static ThreadLocal<String> traceIdHolder = new ThreadLocal<>();public static void clear() {traceIdHolder.remove();}public static void setTraceId(String traceId) {traceIdHolder.set(traceId);}public static String getTraceId() {return traceIdHolder.get();}
}

5、BaseRequest

因为我们需要打印请求入参和出参，那就需要一个统一的request，开发人员开发时，都需要继承该基类

package com.maple.monitor.monitor.request;import java.io.Serializable;
import java.util.HashMap;
import java.util.Map;/*** 所有的request都要继承他*/
public abstract class BaseRequest implements Serializable {protected Map<String, String> extendInfo = new HashMap();public Map<String, String> getExtendInfo() {return extendInfo;}public void setExtendInfo(Map<String, String> extendInfo) {this.extendInfo = extendInfo;}
}

6、BaseResult：

也需要一个统一的result，开发人员开发时，都需要把该类返回

package com.maple.monitor.monitor.result;import java.util.HashMap;
import java.util.Map;/*** 所有的result都要返回他,返回给上游的** @param <T>*/
public class BaseResult<T> {protected T resultObject;protected boolean success;protected String errorCode;protected String errorMessage;protected Map<String, String> extendInfo = new HashMap();public static <T> BaseResult<T> newInstance(T resultObject) {BaseResult baseResult = new BaseResult();baseResult.resultObject = resultObject;baseResult.success = true;return baseResult;}/*** Getter method for property <tt>resultObject</tt>.** @return property value of resultObject*/public T getResultObject() {return resultObject;}/*** Setter method for property <tt>resultObject</tt>.** @param resultObject value to be assigned to property resultObject*/public void setResultObject(T resultObject) {this.resultObject = resultObject;}/*** Setter method for property <tt>success</tt>.** @param success value to be assigned to property status*/public void setSuccess(boolean success) {this.success = success;}/*** Getter method for property <tt>success</tt>.** @return property value of success*/public boolean isSuccess() {return success;}/*** Getter method for property <tt>errorCode</tt>.** @return property value of errorCode*/public String getErrorCode() {return errorCode;}/*** Setter method for property <tt>errorCode</tt>.** @param errorCode value to be assigned to property errorCode*/public void setErrorCode(String errorCode) {this.errorCode = errorCode;}/*** Getter method for property <tt>errorMessage</tt>.** @return property value of errorMessage*/public String getErrorMessage() {return errorMessage;}/*** Setter method for property <tt>errorMessage</tt>.** @param errorMessage value to be assigned to property errorMessage*/public void setErrorMessage(String errorMessage) {this.errorMessage = errorMessage;}public Map<String, String> getExtendInfo() {return extendInfo;}public void setExtendInfo(Map<String, String> extendInfo) {this.extendInfo = extendInfo;}@Overridepublic String toString() {return "BaseResult{" +"resultObject=" + resultObject +", success=" + success +", errorCode='" + errorCode + '\'' +", errorMessage='" + errorMessage + '\'' +", extendInfo=" + extendInfo +'}';}
}

7、BaseInterceptor

拦截器基类，为了排查掉原生方法，新增的拦截器都要继承该基类

package com.maple.monitor.monitor.interceptor;import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;import java.lang.reflect.Method;/*** 拦截器基类*/
public abstract class BaseInterceptor implements MethodInterceptor {@Overridepublic Object invoke(MethodInvocation invocation) throws Throwable {//排除原生方法Method[] methods = Object.class.getMethods();for (Method method : methods) {if (invocation.getMethod().equals(method)) {return null;}}return businessInvoke(invocation);}/*** 子拦截器自行处理** @param invocation* @return* @throws Throwable*/public abstract Object businessInvoke(MethodInvocation invocation) throws Throwable;
}

四、开始编码

1、接口层ApiInterceptor

maple-api-digest.log：接口摘要日志，格式为：[sofaId][接口名.方法名,耗时,结果] 用于最直观的看到接口的大致情况
maple-api-request-result.log：接口请求响应日志，主要是记录我们接口的请求参数和响应结果，帮助排查问题，格式为：[sofaId][接口名#方法名,request:] [sofaId][接口名#方法名,result:]
common-error.log：程序中所有的错误都放进这里

由于这三个日志都是作用于接口层的，所以我们可以一并处理，我们这边使用拦截器来处理。

package com.maple.monitor.monitor.interceptor;import com.maple.monitor.monitor.LogNames;
import com.maple.monitor.monitor.context.ThreadLocalHolder;
import com.maple.monitor.monitor.result.BaseResult;
import org.aopalliance.intercept.MethodInvocation;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;import java.lang.reflect.Method;
import java.util.UUID;public class ApiInterceptor extends BaseInterceptor {private final static Logger LOGGER_API_DIGEST = LoggerFactory.getLogger(LogNames.API_DIGEST);private final static Logger LOGGER_API_REQUEST_RESULT = LoggerFactory.getLogger(LogNames.API_REQUEST_RESULT);private final static Logger LOGGER_COMMON_ERROR = LoggerFactory.getLogger(LogNames.COMMON_ERROR);private final static String EMPTY = "";private final static String BAR = "-";private final static String SEPARATOR = ",";private final static String TAG = "#";private final static String POINT = ".";private final static String MS = "ms";private final static String SUCCESS = "Y";private final static String FAIL = "N";private final static String LEFT_BRACKET = "[";private final static String RIGHT_BRACKET = "]";@Overridepublic Object businessInvoke(MethodInvocation invocation) throws Throwable {Object result = null;long startTime = System.currentTimeMillis();try {initTraceId();logRequest(invocation);result = invocation.proceed();} catch (Exception e) {StringBuilder sb = getTracId();LOGGER_COMMON_ERROR.error("{}", sb.toString(), e);} finally {long elapse = System.currentTimeMillis() - startTime;logResult(invocation, result, elapse);ThreadLocalHolder.clear();}return result;}private void logRequest(MethodInvocation invocation) {StringBuilder sb = getTracId();sb.append(LEFT_BRACKET);sb.append(getMethodSignature(invocation));sb.append(" request: ");sb.append(getStringArguments(invocation.getArguments()));sb.append(RIGHT_BRACKET);LOGGER_API_REQUEST_RESULT.info(sb.toString());}private void logResult(MethodInvocation invocation, Object result, long elapse) {StringBuilder sb = getTracId();sb.append(LEFT_BRACKET);sb.append(getMethodSignature(invocation));sb.append(" result: ");sb.append(result);sb.append(RIGHT_BRACKET);LOGGER_API_REQUEST_RESULT.info(sb.toString());LOGGER_API_DIGEST.info(buildApiDigestLog(invocation, result, elapse));}private String buildApiDigestLog(MethodInvocation invocation, Object result, long elapse) {StringBuilder sb = getTracId();sb.append(LEFT_BRACKET);sb.append(invocation.getMethod().getDeclaringClass().getSimpleName() + POINT + invocation.getMethod().getName());sb.append(SEPARATOR);sb.append(elapse).append(MS);sb.append(SEPARATOR);if (null == result) {sb.append(FAIL);} else {sb.append(((BaseResult) result).isSuccess() ? SUCCESS : FAIL);}sb.append(RIGHT_BRACKET);return sb.toString();}private String getMethodSignature(MethodInvocation invocation) {Method method = invocation.getMethod();return method.getDeclaringClass().getSimpleName() + TAG + method.getName();}private String getStringArguments(Object[] arguments) {if (arguments == null || arguments.length == 0) {return EMPTY;}StringBuilder sb = new StringBuilder();for (int i = 0; i < arguments.length; i++) {if (null != arguments[i]) {sb.append(arguments[i]);}if (i != arguments.length - 1) {sb.append(SEPARATOR);}}return sb.toString();}private void initTraceId() {ThreadLocalHolder.setTraceId(UUID.randomUUID().toString().replace(BAR, EMPTY));}private StringBuilder getTracId() {StringBuilder sb = new StringBuilder();sb.append(LEFT_BRACKET);sb.append(ThreadLocalHolder.getTraceId());sb.append(RIGHT_BRACKET);return sb;}
}

2、持久层DalInterceptor

package com.maple.monitor.monitor.interceptor;import com.maple.monitor.monitor.LogNames;
import com.maple.monitor.monitor.context.ThreadLocalHolder;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;import java.lang.reflect.Array;
import java.lang.reflect.Method;
import java.util.Collection;
import java.util.HashMap;
import java.util.Map;public class DalInterceptor extends BaseInterceptor {private final static Logger LOGGER = LoggerFactory.getLogger(LogNames.DAL_DIGEST);/*** 方法类型表示*/private final static Map<Method, String> METHOD_TYPE_MAP = new HashMap<>();/*** 写类型标识*/protected final String WRITE_TYPE_FLAG = "W";/*** 读类型标识*/protected final String READ_TYPE_FLAG = "R";/*** 读类型方法前缀数组*/protected final static String[] READ_METHOD_PREFIX_ARRAY = {"select", "selects", "get", "query", "find", "list", "count", "batchQuery", "pageQuery", "load", "lock"};/*** log属性分隔串*/protected final static String SEPARATOR = ",";private final static String LEFT_BRACKET = "[";private final static String RIGHT_BRACKET = "]";@Overridepublic Object businessInvoke(MethodInvocation invocation) throws Throwable {long startTime = System.currentTimeMillis();Object result = null;try {result = invocation.proceed();} finally {long elapse = System.currentTimeMillis() - startTime;LOGGER.info(buildDalInfo(invocation, result, elapse));}return result;}private String buildDalInfo(MethodInvocation invocation, Object result, long elapse) {StringBuilder sb = getTracId();sb.append(LEFT_BRACKET);String operationType = getMethodOperationType(invocation.getMethod());sb.append(getMethodSignature(invocation.getMethod()));sb.append(SEPARATOR);sb.append(operationType);sb.append(SEPARATOR);sb.append(elapse).append("ms");sb.append(SEPARATOR);sb.append(StringUtils.equals(operationType, WRITE_TYPE_FLAG) ? "-" : getResultSize(result));sb.append(RIGHT_BRACKET);return sb.toString();}protected String getMethodOperationType(Method method) {String type = METHOD_TYPE_MAP.get(method);if (StringUtils.isBlank(type)) {type = isReadTypeMethod(method.getName()) ? READ_TYPE_FLAG : WRITE_TYPE_FLAG;METHOD_TYPE_MAP.put(method, type);}return type;}private boolean isReadTypeMethod(String methodName) {for (String prefix : READ_METHOD_PREFIX_ARRAY) {if (StringUtils.startsWithIgnoreCase(methodName, prefix)) {return true;}}return false;}protected String getMethodSignature(Method method) {return method.getDeclaringClass().getSimpleName() + "#" + method.getName();}private static int getResultSize(Object result) {if (result == null) {return 0;} else if (result instanceof Collection<?>) {return ((Collection<?>) result).size();} else if (result.getClass().isArray()) {return Array.getLength(result);}return 1;}private StringBuilder getTracId() {StringBuilder sb = new StringBuilder();sb.append(LEFT_BRACKET);sb.append(ThreadLocalHolder.getTraceId());sb.append(RIGHT_BRACKET);return sb;}
}

3、拦截规则

<?xml version="1.0" encoding="UTF-8"?><beans xmlns="http://www.springframework.org/schema/beans"xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"xsi:schemaLocation="http://www.springframework.org/schema/beanshttp://www.springframework.org/schema/beans/spring-beans.xsd"default-autowire="byName"><bean id="apiInterceptor" class="com.maple.monitor.monitor.interceptor.ApiInterceptor"/><bean id="apiInterceptorProxyCreator"class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator"><property name="interceptorNames"><list><value>apiInterceptor</value></list></property><property name="beanNames"><list><value>*Controller</value></list></property></bean><bean id="dalInterceptor" class="com.maple.monitor.monitor.interceptor.DalInterceptor"/><bean id="dalInterceptorProxyCreator" class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator"><property name="interceptorNames"><list><value>dalInterceptor</value></list></property><property name="beanNames"><list><value>*DAO</value></list></property></bean>
</beans>

4、logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration><!-- 控制台输出 --><appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"><encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"><!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern></encoder></appender><!-- COMMON-ERROR-APPENDER --><appender name="COMMON-ERROR-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender"><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!--日志文件输出的文件名--><FileNamePattern>D://logs/common-error.%d{yyyy-MM-dd}.log</FileNamePattern><!--日志文件保留天数--><MaxHistory>15</MaxHistory></rollingPolicy><encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"><!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern></encoder></appender><!-- API-DIGEST-APPENDER --><appender name="API-DIGEST-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender"><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!--日志文件输出的文件名--><FileNamePattern>D://logs/maple-api-digest.%d{yyyy-MM-dd}.log</FileNamePattern><!--日志文件保留天数--><MaxHistory>15</MaxHistory></rollingPolicy><encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"><!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern></encoder></appender><!-- API-REQUEST-RESULT-APPENDER --><appender name="API-REQUEST-RESULT-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender"><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!--日志文件输出的文件名--><FileNamePattern>D://logs/maple-api-request-result.%d{yyyy-MM-dd}.log</FileNamePattern><!--日志文件保留天数--><MaxHistory>15</MaxHistory></rollingPolicy><encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"><!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern></encoder></appender><!-- DAL-DIGEST-APPENDER --><appender name="DAL-DIGEST-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender"><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!--日志文件输出的文件名--><FileNamePattern>D://logs/maple-dal-digest.%d{yyyy-MM-dd}.log</FileNamePattern><!--日志文件保留天数--><MaxHistory>15</MaxHistory></rollingPolicy><encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"><!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern></encoder></appender><!--common error--><logger name="COMMON-ERROR" additivity="false"><level value="{logging.level.root}"/><appender-ref ref="COMMON-ERROR-APPENDER"/></logger><!--api digest--><logger name="API-DIGEST" additivity="false"><level value="{logging.level.root}"/><appender-ref ref="API-DIGEST-APPENDER"/></logger><!--api template--><logger name="API-REQUEST-RESULT" additivity="false"><level value="{logging.level.root}"/><appender-ref ref="API-REQUEST-RESULT-APPENDER"/></logger><!--dal--><logger name="DAL-DIGEST" additivity="false"><level value="{logging.level.root}"/><appender-ref ref="DAL-DIGEST-APPENDER"/></logger><!--指定最基础的日志输出级别--><root level="{logging.level.root}"><!--appender将会添加到这个loger--><appender-ref ref="STDOUT"/></root></configuration>

注意：不要忘记主类类需要引入我们自定义xml哦

package com.maple.monitor;import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.ImportResource;@ImportResource(locations = {"classpath:monitor-spring.xml"})
@SpringBootApplication
public class MonitorLogApplication {public static void main(String[] args) {SpringApplication.run(MonitorLogApplication.class, args);}}

五、测试

1、正常测试

测试类 UserController

package com.maple.monitor.controller;import com.maple.monitor.entity.UserDO;
import com.maple.monitor.entity.request.UserLoadRequest;
import com.maple.monitor.monitor.result.BaseResult;
import com.maple.monitor.service.UserService;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;@RestController
public class UserController {@Autowiredprivate UserService userService;@GetMapping("/queryUser")public BaseResult<UserDO> queryUser(UserLoadRequest request) {UserDO userDO = userService.selectByUserId(request.getUserId());System.out.println(userDO);return BaseResult.newInstance(userDO);}
}

启动项目，浏览器访问 http://localhost:8080/queryUser?userId=123

打开我们本地logs，可以看到日志目录已经生成

打开每一个文件，看下日志格式

maple-api-digest：api接口摘要日志

maple-api-request-result：api接口入参参数日志

maple-dal-digest：持久层日志

但是common-error是空的，因为没有异常发生。

2、异常测试

我们下面测试如果发生异常时，common-error里会不会有数据

把sql改错

重启并访问接口

maple-api-digest：api接口摘要日志

maple-api-request-result：api接口入参参数日志

maple-dal-digest：持久层日志

common-error：

六、git源码

https://gitee.com/gane_maple/monitor-log